当前位置: 首页 > 后端技术 > PHP

【PHP问题定位】php-fpmidle分析

时间:2023-03-30 02:46:13 PHP

顺风车运营研发团队熊浩涵问题现象在线报警群中,有零星的php-fpm-idle报警,持续时间很短(几秒甚至一个second),见下图问题分析。当出现故障时,我们可以通过观察故障时间前后相关指标的异常变化来找出故障原因。常用指标如下:cpu_idlephp-fpm-idleionginx.status.flowopcachereset指标截图如下:io.readnginx.statusopcachereset出现故障时(php-fpm-idle掉线),除了nginx的499是显着增加和io增加,其余性能指标没有显着变化。值得注意的是,失败时间与opcachereset时间高度重合。opcachereset是上线时的一个操作,会清除服务器上的phpopcache。所以,有两种可能:单纯是清opcache导致的故障,php需要重新解析php文件,耗时增加,php-fpm-idle减少;在线过程中进行的一些操作影响了一些url请求的效率,导致Timeout(nginx中有大量499)也导致php-fpm-idle掉线;nginx_499:部分请求长时间占用php-fpm进程(死循环或超时),导致新请求排队,php-fpm-idledropped。cpu-idle:cpu-idle和php-fpm-idle没有直接关系,但是会相互影响。当请求数增加时,php-fpm启动更多进程处理请求,自然会增加cpu消耗,cpu_idle减少;当cpu_idle减少时(cpu更忙),php需要比平时更多的时间来处理请求,结果,请求堆积而php-fpm-idle下降。io:磁盘io会直接影响fpm进程读写文件。io太高会导致文件读写变慢。同时过高的io也会影响cpu-idle,进而间接影响php-fpm。日志采集系统对采集到的性能指标数据进行聚合操作。比如A10s指标采集一次,当天可以查看10s粒度的数据。但是对于历史数据,比如7天前,数据粒度不再是10s,而是15分钟,odin对数据进行聚合。这意味着一些“尖峰数据”随着时间的推移,它的峰值不再存在,曲线会变得更平滑。定位问题查看报警机的nginxaccess.log,取之前请求的traceid,查看业务日志,发现大量apollo(内部服务)请求超时,proc_time时间为太长。在查看nginx日志的时候,发现在499日志中,request_time是根据客户端断开连接的时间来计算的。例如API请求超时时间为0.08s。超时后,请求者主动断开连接。此时nginx打印了一条499的日志(略长于0.08s)。但实际上php-fpm的处理还在继续,经过较长时间后,tracelog中才打印出真正的执行时间(proc_time)。查到这里,我的猜测是:因为线上操作触发了Apollo(内部服务)某种异常,此时所有Apollo链接超时,导致nginx出现大量499,同时也导致php-fpm-空闲的底部。为了验证这个猜想,需要解决以下两个问题:(1)上线与Apollo超时是否存在必然联系?需要多找几个例子验证一下(2)既然只要在线就会触发这个问题,为什么不是每台机器都报警,而是零星的报警?我们先来看问题(1),结果令人振奋。找了几台机器验证了一下,上线时间恰逢业务日志出现大量“callapollotoolong”的时间。周三晚上增加了Apollo超时的监控,周四观察了上线期间Apollo超时指标的变化,时间也刚好吻合。8月9日下午15时22分,又报了警。同时监控Apollo超时:*.16.gz01.17.gz01.17.gz01同时列出17.gz01机器指标的目的是为了说明,虽然17.gz01没有报警,但是17台机器的指标变化与16台一致。再看问题(2):我的猜测是由于故障时间短(机器日志中只有100ms左右),而odin在最短的10s内收集一次指标,大部分机器php-fpm-idle丢弃的数据尚未收集到。结语在上线过程中清除了php的opcache,这样当下一个请求到来时,代码中的Apollo会读取本地的配置文件,io会增加,而php需要重新解析文件,io会进一步增加,时间消耗会增加。它导致php-fpm-idle暂时下降。