发现问题

一个laravel脚本执行花了快2小时,查看业务逻辑为遍历数据表,第一反应为mysql查询条件原因.排查后不是,是循环里对数组进行频繁的读和写很慢.

排查问题

• 将循环写成一个test.php ,用php test.php执行,很快0.1秒不到执行完了.但是通过php artisan执行的确很慢,要不到3分钟.用strace检查一下都在做什么

strace -o output.txt -T -tt -e trace=all php artisan  ArrayTest
strace -o output.txt -T -tt -e trace=all php test.php

测试代码如下

$s1 = microtime(1);
$a = [];
for ($i = 0; $i < 150000; $i++) {
    //故意做读取，并跳过
    if ($a[$i] == 111) {
        continue;
    }
    // 写
    $a[$i] = 23;
    if ($i % 1000 == 0) {
        $m = round(memory_get_usage()/1024/1024,2);
        var_dump(date("H:i:s") . ' id ' . $i. " mem " .$m);
    }
}
$s2 = microtime(1);
var_dump(($s2 - $s1));     

通过对比发现artisan执行的代码一直在释放和重新申请内存中的一个固定地址,如图

• 以上测试只在部分机器会有问题, 和没问题的机器的区别为php版本不同,php有开启opcache,先从php配置下手,通过使用不同的ini配置发现都没改善,关闭opcache测试也没有改善.但是如果php代码里把$a[$i]的读取前加一个isset判断就会快了,但是这很难保证所有数组操作前都有isset呀
• 接下来编译不同php版本测试,发现有问题机器换了php版本(7.4.5 和7.4.9)bug就不存在了.那应该就是此版本的bug.查了7.4.9发现修复了一大堆bug,其中3条都和数组有关系,我在不会出问题的机器也装7.4.8也出现问题了,也验证了问题所在.

• 但是为什么test.php又会执行的快呢? 为了弄清楚问题,我又装下载了一个空的laravel框架,然后加上这个脚本,测试时遇到了一个提示

当然可以通过

error_reporting(E_ALL & ~E_NOTICE);

屏蔽掉报错,之前的代码库就有屏蔽所以没有看到过这个提示,屏蔽完发现用7.4.8版本执行还是很慢,我于是想难道是因为这个notice级别的错误?跟着提示查看了Illuminate\Foundation\Bootstrap\HandleExceptions文件并把test.php做了修改

<?php
set_error_handler('handleError');
function handleError($level, $message, $file='',$line=0,$context=[])
{
}

error_reporting(E_ALL & ~ E_NOTICE);
$s1 = microtime(1);
$a = [];
for ($i = 0; $i < 150000; $i++) {
        if ($a[$i] == 111) {
                continue;
        }
        $a[$i] = 23;
        if ($i % 1000 == 0) {
                $m = round(memory_get_usage()/1024/1024,2);
                var_dump(date("H:i:s") . ' id ' . $i. " mem " .$m);
        }
}
$s2 = microtime(1);
var_dump(($s2 - $s1));

执行后发现test.php也变慢了,说明和laravel也没有关系.要触发问题就是要3个点

php 7.4.8 + notice级别错误 + set_error_handler捕获错误

到这边问题就算定位好了.

补丁验证

我根据https://bugs.php.net/bug.php?id=78598找到了https://github.com/php/php-src/pull/5149 可惜的是替换代码后bug并没有消失,那能解决问题的补丁又是哪个呢?

通过比较php7.4.9和php7.4.8源码的差异,主要看Zend目录,反复编译测试,由最初的多个文件

modified: Zend/zend.c
modified: Zend/zend_closures.c
modified: Zend/zend_compile.c
modified: Zend/zend_exceptions.c
modified: Zend/zend_execute.c
modified: Zend/zend_generators.c
modified: Zend/zend_hash.c
modified: Zend/zend_object_handlers.c
modified: Zend/zend_vm_def.h
modified: Zend/zend_vm_execute.h

到最后定位到只有Zend/zend.c是影响此bug的文件, 再根据差异代码反查commit得到bug修复地址 https://github.com/php/php-src/commit/a3cb6122430cb43877a558f51f78bffd78cb86ca (Fixed bug #97599 (coredump in set_error_handler))故障排查结束