【PHP问题定位】2018-07-02 fpm掉底分析

顺风车运营研发团队 黄桃

问题现象
某机器这段时间出现cpu-idle掉地的报警 如图：

原因分析

查看当时的监控（php-fpm-idle、cpu-idle，io-wait、io-write 等）
（1）php-fpm-idle今天出现两次突降，一次是12点左右，一次是16：30左右，查看整周也经常出现突降，如图

（2）io-wait在11：58分时 突然升高

（3）io-write也在11：58时出现大量写：

（4）cpu-idle当时短暂出现降低，之后出现徒增，但是结合整周的曲线来看，一直维持在70-80之间，徒增原因待分析：

（5）原因推测：因为当时出现了大批量的写日志，导致io-wait上升，php-fpm进程因为写文件出现延时，造成整体响应过慢，从而导致了fpm掉地; 对同一个文件进行 write时，大批量并行会出现等待，阻塞

验证推测
（1）查看当时的php-fpm的慢日志，看当时阻塞的地方，基本是在调用fwrite阻塞

（2）查看当时的程序日志trace.log的大小，日志文件越大的时间段，正好是fpm-idle下滑严重的阶段：

（3）在通过 sar命令，验证下当时的写入磁盘情况，在出现掉地的时间段确实出现极大的写入，wr_sec/s 从每秒几百低峰的几百增长到十几万：

问题原因及优化建议
写入日志大可能两方面原因：

（1）当时请求暴增
（2）请求未暴增，但是某些请求触发了某些不合理的打日志
验证原因1，出现问题时间段每秒的流量

32 [02/Jul/2018:12:01:12
18 [02/Jul/2018:12:01:13
18 [02/Jul/2018:12:01:14
42 [02/Jul/2018:12:01:15
30 [02/Jul/2018:12:01:16
35 [02/Jul/2018:12:01:17
26 [02/Jul/2018:12:01:18
30 [02/Jul/2018:12:01:19
1 [02/Jul/2018:12:01:22
108 [02/Jul/2018:12:01:24
17 [02/Jul/2018:12:01:25
1 [02/Jul/2018:12:01:27
1 [02/Jul/2018:12:01:29
1 [02/Jul/2018:12:01:30
9 [02/Jul/2018:12:01:33
1 [02/Jul/2018:12:01:31
1 [02/Jul/2018:12:01:32
146 [02/Jul/2018:12:01:33
62 [02/Jul/2018:12:01:34
44 [02/Jul/2018:12:01:35
1 [02/Jul/2018:12:01:37
1 [02/Jul/2018:12:01:38
1 [02/Jul/2018:12:01:41
2 [02/Jul/2018:12:01:44
2 [02/Jul/2018:12:01:50
1 [02/Jul/2018:12:01:45
12 [02/Jul/2018:12:01:50
2 [02/Jul/2018:12:01:45
7 [02/Jul/2018:12:01:50
1 [02/Jul/2018:12:01:46
1 [02/Jul/2018:12:01:50
1 [02/Jul/2018:12:01:46
15 [02/Jul/2018:12:01:50
7 [02/Jul/2018:12:01:48
2 [02/Jul/2018:12:01:50
1 [02/Jul/2018:12:01:48
342 [02/Jul/2018:12:01:50
65 [02/Jul/2018:12:01:51
46 [02/Jul/2018:12:01:52
54 [02/Jul/2018:12:01:53
1 [02/Jul/2018:12:01:55
1 [02/Jul/2018:12:01:56
1 [02/Jul/2018:12:01:57
1 [02/Jul/2018:12:01:59
16 [02/Jul/2018:12:02:03
1 [02/Jul/2018:12:02:01
1 [02/Jul/2018:12:02:02
42 [02/Jul/2018:12:02:03
1 [02/Jul/2018:12:02:02
187 [02/Jul/2018:12:02:03
39 [02/Jul/2018:12:02:04
40 [02/Jul/2018:12:02:05
25 [02/Jul/2018:12:02:06
44 [02/Jul/2018:12:02:07
29 [02/Jul/2018:12:02:08

正常情况是QPS是30左右，出问题时间段则非常不稳定，时高时低，相差非常大，例如在 12:01:50 时 342 qps，但是前十几秒则基本都是个位数；原因？前几十秒都阻塞了，响应不了，积累到了12:01:50才响应；整体流量并未出现暴增；

验证原因2，查看当时traceId日志，查看写进去的内容：

发现这段写入非常巨大，一行就119kb ，总共写了 33555 行，总大小占：33555 * 119KB = 3993045KB =3899M 基本可以断定为这行出的问题了

优化建议：在底层打日志的类中对字符串长度做限制，避免这种大批量的写入；