一、背景

2021-05-13 14:10 服务上线后，开始出现大量“Call to undefined method”错误。通过Grafana，通过查看日志文件，可以发现以下发现

• 错误发生在5台服务器上
• 每台服务器上报的错误持续时间约为3秒

2。问题排序

1.上线时间轴

• 14:10:50 登录上线
• 14:10:57 数据准备完成
• 14:10:57 开始上线
• 14:10:57 同步目录文件通过并行 rsync 与目标服务器
• 14:11:26 第一个服务器同步已完成
• 14:11:41 最后一个服务器同步已完成
• 14:11:41 在线完成

2.服务器 1 时间线

• 14 :11:35 代码与服务器同步完成
• 14:11:36 第一个 bug 报告开始
• 14:11:37 最后一个 bug 报告结束（耗时 1第二，共220个帖子）

3。服务器 2 时间线

• 14:11:35 代码同步到服务器完成
• 14:11:35 第一个 bug 报告开始
• 14:11:38 最后一个 bug 报告结束（耗时 3 秒，237 条消息）总共）

4。服务器 3 时间轴

• 14:11:35 代码同步到服务器完成
• 14:11:36 第一个 bug 报告开始
• 14:11:40 最后一个 bug 报告结束（耗时 4 秒，700 条）共）

5，服务器 4 时间线

• 14:11:39 代码同步到服务器完成
• 14:11:45 第一个 bug 报告开始
• 14:11:45 最终结束Bug 报告（耗时 1 秒，共 196 个）

6，服务器 5 时间轴

• 14:11:28 代码与服务器同步完成
• 14:11:30 第一个报错开始
• 14:11:32 最后一个报错结束（持续2秒，共399条信息） )

3.问题分析

1.完整错误消息

错误消息是调用了一个不存在的方法

{
    "logtime":"2021-05-13 14:11:45",
    "Mode":"fpm-fcgi",
    "Msg":"Call to undefined method app\\xxx\\services\\xxx\\XXXService::doSomething()",
    "Trace":"\/home\/xxx\/xxxxxx\/xxxx.php(68)\n#0 {main}",
    "Uri":"\/xxx.php?xxxxxxxxxxxxxx",
    "Clientip":"xx.xx.xx.xx"
}

2。问题混乱

根据打印的调用堆栈，发现在xxx.php。从当时的Git提交记录来看，方法doSomething()是存在的。也就是说，这个方法不被发现也没有问题。 ？ ，调用者的文件代码已同步，但包含方法 doSomething() 的文件尚未同步

(2) opcache 问题

两个文件都与目标机同步，但是当Zend引擎解析代码，opcache有如下分布情况

4。根本原因分析

(1) 在线问题

看在线脚本，预计上传项目大约需要 32 秒。线上平台日志显示，从上线到所有机器同步完成，耗时30秒。

• 问题时间线中，文件上传完成后开始出现错误信息
• 实际上传时间超过30秒，与预估的32秒基本一致

从以上两个结论我们可以排除网上的问题，即代码文件。确实一切都正常同步了

（2）opcache问题

①opcache伪代码

$now = time();
if( isOpcached(file) ){
  
    // check opcache code
    if( $now - file.lastUpdatedTime < revalidate_freq ){
      
        // 读opcache
        return getOpcache(file);
    }
}

// 重新解析PHP文件
$result = reParse(file);
writeOpcache(file, $result);
return $result;

②opcache执行原理

③opcache中文件的最后更新时间不均匀

因为同步代码文件，到达服务器需要30秒，所以opcache中每个文件的最后更新时间会不均匀

④ 结论

因为opcache中每个文件的最后更新时间会不均匀，所以会出现以下情况

• 发送引擎检查A文件的opcache时，发现缓存已经过期，所以会解析新的A文件
• B文件在opcache中的最后更新时间是很近的，即也就是说，opcache中的B文件。内容还在有效期内
• Zend引擎直接读取opcache中B文件的内容，但是这个内容是旧的

理论上会存在上述场景，但需要测试复现。如果可以重现，则可以确认这是最后一次缓存的 AB 文件更新。无需重新解析B文件

4. 重现opcache导致PHP错误

1.测试准备

(1) opcache 配置

opcache 配置如下，有效期为 5 秒

(2) 7 个测试脚本

• online.sh：在线脚本，用于模拟在线actions

cat TestController.php > /home/TestController.php
cat TestService.php > /home/TestService.php

• rollback.sh：回滚脚本，用于模拟回滚操作

cat TestControllerOld.php > /home/TestController.php
cat TestServiceOld.php > /home/TestService.php

• TestControllerOld.php：旧的Controller文件，即回滚后的Controller内容（调用getOpcacheStatus1方法）

<?php

class TestController {

    public function test(){
         phpinfo();
    }

    public function test2(int $number){

	// opcache_invalidate(__FILE__, true);
        $opcache = TestService::getInstance()->getOpcacheStatus1();
	      $this->result = [
	        'number' => $number,
	        'opcache' => $opcache,
    	    'time' => date('Y-m-d H:i:s'),
        ];

    }
}

• TestController.php：新的Controller文件，即上线后的Controller内容（调用getOpcacheStatus2方法）

<?php

class TestController {

    public function test(){
         phpinfo();
    }

    public function test2(int $number){

	// opcache_invalidate(__FILE__, true);
        $opcache = TestService::getInstance()->getOpcacheStatus2();
	      $this->result = [
	        'number' => $number,
	        'opcache' => $opcache,
    	    'time' => date('Y-m-d H:i:s'),
        ];

    }
}

• TestServiceOld.php：旧服务文件，即回滚后的Service内容（不调用getOpcacheStatus2方法）

<?php

class TestService
{

        public function getOpcacheStatus1(){
	          return 1;
        }

}

• TestService.php ：新服务文件，即上线后的服务内容（通过getOpcacheStatus2方法）

<?php

class TestService
{

        public function getOpcacheStatus1(){
	          return 1;
        }

        public function getOpcacheStatus2(){
		        sleep(1);
		        return 2;
        }
}

• loop.php：循环脚本，用于连续按顺序执行上线/回滚操作

<?php

while(1){
    sleep(1);
    echo "上线\n";
    system('bash ./online.sh');
    sleep(1);
    echo "回滚\n";
    system('bash ./rollback.sh');
}

2。测试计划

(1) 测试方法

通过在线和离线不断执行，可以增大不同缓存文件的最后更新时间的差异。在这种高层环境下，在概率和保持高QPS访问的情况下，更容易重现Call to undefined method错误

• 运行循环脚本，即按顺序运行线上线下操作，无需中断
• 启动Go脚本并发请求接口，QPS为100

执行前两步，然后观察tail -f /home/log/sys_fatal.log日志

( 2) 预期结果

出现在日志中调用未定义的方法 getOpcacheStatus2 错误

(3) 预期结论

如果出现上述错误，则说明 PHP 有问题本身。结果在opcache中，控制器的内容更新了，但是服务的内容却没有

3。测试流程

执行完所有挂起的操作后，开始观察日志，很快就会不断出现预期的 Call to undefined method 错误，如下图如图

4。测试结论 在线同步文件时间越长，每个文件最后更新时间相差越大

5.测试总结

当可以确认所有文件都是最新的时，同步文件的时间越长，每个文件的最后更新时间差异就越大，这是PHP opcache造成的上线后出错的几率越高

4.问题总结

因为在线同步文件需要30秒，所以调用方文件和被调用文件对应的最后更新时间两者必须不同opcache 中的文件。最后更新时间不一致。根据当时的日志文件可以确定QPS在100以上，导致由于opcache导致PHP错误

作者：Wgrape
来源：稀土掘金