记一次 CPU 忙碌导致的超时

通过业务日志发现客户端调用某一远程服务时不时连接超时,导致部分业务请求受影响,以下记录了定位的过程
首先收集 thrift 代理日志,统计该服务超时情况,结果如下:

**@ubuntu:/data/log/ServiceAgent_d$ zgrep 'time out' ServiceAgent_d.log.*.gz |awk '{print $3,$7,$12}'|grep od
11:11:20 od_getById ***.***.112.152_60008
14:11:25 od_listByParam ***.***.112.152_60008
19:11:25 od_getById ***.***.112.152_60008
19:11:27 od_getById ***.***.112.152_60008
00:12:02 od_ping ***.***.112.152_60008
05:10:30 od_ping ***.***.112.152_60008
05:11:37 od_ping ***.***.112.152_60008
21:11:37 od_getById ***.***.112.152_60008
21:11:49 od_listByParam ***.***.112.152_60008
10:10:11 od_listByParam ***.***.112.152_60008
11:11:31 od_listByParam ***.***.112.152_60008
14:10:24 od_listByParam ***.***.112.152_60008
14:11:34 od_getById ***.***.112.152_60008
11:11:39 od_listByParam ***.***.112.152_60008
13:11:39 od_listByParam ***.***.112.152_60008
20:11:26 od_listByParam ***.***.112.152_60008
21:11:33 od_listByPage ***.***.112.152_60008
21:11:38 od_listByParam ***.***.112.152_60008
10:11:43 od_listByParam ***.***.112.152_60008
11:11:26 od_getById ***.***.112.152_60008
14:11:36 od_getById ***.***.112.152_60008
17:11:42 od_getById ***.***.112.152_60008
11:10:10 od_listByParam ***.***.112.152_60008
15:10:13 od_listByParam ***.***.112.152_60008
19:11:26 od_listByParam ***.***.112.152_60008
14:10:30 od_listByPage ***.***.112.152_60008 
16:10:18 od_listByPage ***.***.112.152_60008
20:10:30 od_listByParam ***.***.112.152_60008
**@ubuntu:/data/log/ServiceAgent_d$

左右端详,可以发现以下特点:具有周期性,而且集中在 152 机器上,都是每个小时的10分钟左右出现
接下来查看机器运行情况:

可看到 CPU 也是有规律的升高.
通过应用部署架构已知该主机上有定时任务 task 类型的应用,所以初步怀疑是某些 task 进程有问题

接下来进入该 152 机器,使用 top 命令观察 CPU,等待下一个周期,等到 11 分钟时,得到以下截图: 得知占用最大的程序为 gzip ,但是查不到 gzip 进行什么操作,无解
另辟蹊径,咨询运维得知:每小时的第 10 分钟,logrotate 会对日志进行压缩轮转,如下图:
所以定位的重点就变成:是否是某些日志设置不当,导致 logrotate 异常
检查 logrotate 运行状态:
grep 10-20 /var/lib/logrotate/status
检查 logrotate 操作的文件大小
grep 10-20 /var/lib/logrotate/status |awk -F '"' '{print $2}'|xargs ls -alh
倒数第二行,发现文件大小异常,检查日志文件所属程序,发现是遗留的 kafka 程序
解决方案: 关闭它
观察日志,没有发现超时,问题解决

2017-11-20