使用php记录业务日志有没有遇到过内容错乱的情况?一位好朋友最近就遇到了这个情况。 php-fpm 是多进程运行的,记录日志的话就会导致多进程同时写一个日志文件。看起来是有写乱的隐患的,我和这位朋友讨论了很久,发现事实没这么简单。

复现现场

我们开启26个进程,每个进程都将100行日志 append 写入到相同的日志文件。 每行日志都是由 a~z 26个字母的其中一个重复10240次组成。如果最后检测到某一行不全是相同的字母,那么说明写乱了。

<?php

// 初始化日志文件
$fileName = "fwrite.log";
if (file_exists($fileName)) {
    unlink($fileName);
}

// 进程数量
$pNum = 26;
// 每行日志长度
$msgLen = 10240;
// 模拟日志内容
$letterArr = range('a', 'z');


// 创建26个进程
for($i = 0; $i < $pNum; $i++) {
    $son = pcntl_fork();
    if ($son === -1) {
        throw new Exception("fork fail");
    } else if ($son === 0) {
        // 记录日志
        $content = str_repeat($letterArr[$i], $msgLen);
        $fd = fopen($fileName, 'a');
        for ($i=0; $i < 100; $i++) { 
            fwrite($fd, $content . "\n");
        }

        exit(0);
    }
}

$pExitNum = 0;
while(1) {
    usleep(300);
    //挂起主进程,主进程用来控制子进程
    $status = 0;
    $pid = pcntl_wait($status, WUNTRACED);
    if ($pid > 0) {
        //如果有子进程退出,可以做一些事情。比如记录日志,重新生成一个子进程
        $pExitNum++;
    }
    if ($pExitNum == $pNum) {
        break;  
    }
}

// 日志写完了
echo "日志写完了\n";
echo "检测乱序......\n";

$fd = fopen($fileName, 'r');
$line = 1;
while (($row = fgets($fd)) !== false) {
    $firstChar = $row[0];
    if (!preg_match('/^' . $firstChar . '{' . $msgLen . '}$/', $row)) {
        echo "line:{$line} concurrent error.\n";
    } else {
        echo "line:{$line} pass.\n";
    }
    $line++;
}

echo "end\n";

分析原因

执行上面的代码很容易就能复现问题,理论上来讲不应该出现这样的情况,因为我们是 append 写入的,系统已经保证了我们写入的原子性。 写入日志的流程可以简化为下面的形式。

lock -> write 10240byte -> unlock

那么能出现问题的情况只有 php 将一条 10240byte 的数据分成多条来写了,也就是下面的形式。

lock -> write 8192byte -> unlock
lock -> write 2048byte -> unlock

这样的话,某一进程刚写一部分数据,可能就切换到别的进程去写了,多进程同时写也就会写乱了。

为了验证猜测的真实性,我们用 strace 工具来追踪,写入 10240byte 数据,php总共会执行了多少次 write 系统调用? 答案是每次都是 write 两次,第一次永远是 8192byte,毕现。和我们猜测的完全一致。

然后我们把上面脚本中的 10240 改成 小于8192的数据,就再也没有发现写乱的情况。也就是说php写入日志想要保证原子性,一条的数据量要小于 8kb。

源码

为什么是 8192byte 这个长度限制,我们追了下php的源码。

/* Writes a buffer directly to a stream, using multiple of the chunk size */
static ssize_t _php_stream_write_buffer(php_stream *stream, const char *buf, size_t count)
{
    ......

    while (count > 0) {
        size_t towrite = count;
        if (towrite > stream->chunk_size)
            towrite = stream->chunk_size;

        justwrote = stream->ops->write(stream, buf, towrite);
        ......
    }

    return didwrite;
}

上面的源码可以看出,每次写入的时候都是分块来写的,然后我们查下这个分块的大小。

file_globals_p->def_chunk_size = PHP_SOCK_CHUNK_SIZE;
#define PHP_SOCK_CHUNK_SIZE	8192

查到这里就彻底明白 8192 这个限制的来源了。

上面看的是 php7.4.1 的源码,然后我们又看了下 php8 的源码,发现已经没有8192的限制了😂,php收到数据后不做分块处理,直接 write 一次性写完。

总结

想要在php8以前避开这个坑,写日志的时候需要注意下,一条不要超过8kb的大小。当然一般很少会写这么大的日志。