使用 php 记录业务日志有没有遇到过内容错乱的情况？一位好朋友最近就遇到了这个情况。
php-fpm 是多进程运行的，记录日志的话就会导致多进程同时写一个日志文件。看起来是有写乱的隐患的，我和这位朋友讨论了很久，发现事实没这么简单。
复现现场#
我们开启 26 个进程，每个进程都将 100 行日志 append 写入到相同的日志文件。
每行日志都是由 a~z 26 个字母的其中一个重复 10240 次组成。如果最后检测到某一行不全是相同的字母，那么说明写乱了。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
| <?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 写入的，系统已经保证了我们写入的原子性。
写入日志的流程可以简化为下面的形式。
1
| lock -> write 10240byte -> unlock
|
那么能出现问题的情况只有 php 将一条 10240byte 的数据分成多条来写了，也就是下面的形式。
1
2
| lock -> write 8192byte -> unlock
lock -> write 2048byte -> unlock
|
这样的话，某一进程刚写一部分数据，可能就切换到别的进程去写了，多进程同时写也就会写乱了。
为了验证猜测的真实性，我们用 strace 工具来追踪，写入 10240byte 数据，php 总共会执行了多少次 write 系统调用？
答案是每次都是 write 两次，第一次永远是 8192byte，毕现。和我们猜测的完全一致。
然后我们把上面脚本中的 10240 改成 小于 8192 的数据，就再也没有发现写乱的情况。也就是说 php 写入日志想要保证原子性，一条的数据量要小于 8kb。
为什么是 8192byte 这个长度限制，我们追了下 php 的源码。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
| /* 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;
}
|
上面的源码可以看出，每次写入的时候都是分块来写的，然后我们查下这个分块的大小。
1
2
| 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 的大小。当然一般很少会写这么大的日志。