您的位置 首页 php

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

文章来源:智云一二三科技

文章标题:「PHP问题定位」php-fpm的idle掉底分析

文章地址:https://www.zhihuclub.com/152209.shtml

关于作者: 智云科技

热门文章

网站地图