【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有一瞬间的掉底。