发现问题

一个 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捕获错误

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

补丁验证

我根据找到了 可惜的是替换代码后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修复地址 ( Fixed bug #97599 (coredump in set_error_handler) )故障排查结束