【PHP问题定位】php-fpm的idle掉底分析

顺风车运营研发团队 熊浩含

问题现象

线上报警群里时而有php-fpm-idle的零星报警，持续时间很短（几秒甚至一秒），见下图

问题分析

发生故障时，我们可以通过观察相关指标在故障时间的前后异常变化，找出故障原因。常用的指标如下：

• cpu_idle
• php-fpm-idle
• io
• nginx.status.flow
• opcachereset

指标截图如下：

io.read

nginx.status

opcachereset

在故障发生时（php-fpm-idle掉底），除了nginx的499明显增多，io增大外，其余性能指标并无明显变化。值得注意的是，故障时间与opcachereset时间高度重合，opcachereset是上线时的操作，会清除服务器上的phpopcache。故有两种可能：

• 故障单纯是清除opcache导致的，php需要重新解析php文件，耗时增加，php-fpm-idle下降;
• 上线时进行的某些操作，影响了某些url请求的效率，导致超时(nginx出现大量499)，也引起了php-fpm-idle下降;

nginx_499:部分请求长时间占用了php-fpm进程（死循环或者超时），导致了新请求的排队，php-fpm-idle下降。

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对数据做了聚合。这意味着一些”尖峰数据“随着时间推移，其尖峰不再，曲线会变得平滑。

问题定位

查看报警机器的nginx的access.log

取前几处请求的traceid，在业务日志中查看，发现大量的apollo（一个内部服务）请求超时，proc_time时间过长

在看nginx日志的时候发现，499的log中，request_time是以客户端断开连接的时间计算的。例如api的请求超时时间是0.08s，超时后请求方主动断开，此时nginx即打印了499的log（比0.08s稍长）。但实际上php-fpm的处理仍在继续，过了更长的时间后，在trace日志中打印了真正的执行时间（proc_time）。

查到这里，我的猜想是：因为上线操作触发了阿波罗(一个内部服务)的某种异常，导致阿波罗链接在这一瞬间全部超时，引起nginx的大量499，也引起了php-fpm-idle的掉底。

验证这个猜想需要解决以下两个问题：

• (一) 上线和阿波罗超时是否有必然的联系？需要多找几个例子验证
• (二）既然只要上线就会触发这个问题，为啥不是每台机器都报警，而只有零星的报警？

先看问题（一），结果是振奋人心的，找了几台机器验证，上线时间和业务日志中大量出现”call apollo too long“的时间重合。周三晚加上了对阿波罗超时的监控，周四观察上线期间阿波罗超时指标的变化，时间也吻合。

8月9日下午15：22又报了一次警

与此同时的阿波罗超时监控:

*.16.gz01

.17.gz01

.17.gz01

这里同时列出17.gz01机器指标的目的是为了说明，尽管17.gz01没有报警，但17机器的指标变化和16是统一的。

再看问题（二）：我的猜想是，由于故障时间很短（看机器日志只有100ms左右）,而odin最短10s采集一次指标，大部分机器php-fpm-idle掉底的数据并没有被采集到。

结论

上线过程中清除了php的opcache，导致下一时刻的请求到来时，代码中的阿波罗会读取本地配置文件，io增加，而php需要重新解析文件，io进一步增大，耗时增加，导致php-fpm-idle有一瞬间的掉底。