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

最新推荐文章于 2021-05-25 15:05:16 发布

跑焦

最新推荐文章于 2021-05-25 15:05:16 发布

阅读量242

点赞数

文章标签： php-fpm io

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

问题现象

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

问题分析

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

cpu_idle

php-fpm-idle

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又报了一次警