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