前些日子,监控显示线上偶尔发生请求两秒超时的情况。解决这个问题前前后后花了不少时间,也走了一些弯路。这里记录下来备忘。
前期分析
首先需要了解一下我们的服务:
我们的服务是一组无状态的前端服务器加上有状态的后端存储层。
这些服务都部署在腾讯云黑石服务器上面。
第一件事是要定位问题出现在前端还是后端。通过日志,我们发现在出错时间段里,每个前端服务器都有报错,并且出错请求都是发往同一后端服务器的。由此可见,问题出现在后端服务上。
接下来,需要分析出错的特征。通过日志发现错误都是因为前端两秒超时导致,而后端在前端超时之后事实上是完成了请求。因为是存储服务,我们自然在第一时间就查看了磁盘的情况。果然,在出错时,磁盘的io.util非常高(sar -dp的输出,从第4列开始分别是tps rd_sec/s wr_sec/s avgrq-sz avgqu-sz await svctm %util):
需要注意的是:
io.util非常高,且只持续了2~3秒
几乎所有盘的io.util都高
io的tps和吞吐并不高
另外,还发现了另外一个规律:单台机器,大概每12小时左右会出现io.util高,并伴随着超时出错:
问题排查
快速排查
我们做了一些快速排查,试图以比较小的代价找到问题的根源:
查看系统的定时任务
查看系统日志
查看存储服务代码中的定时任务
可惜,都没有发现有价值的线索。于是推测,一定是有一个我们不知道的存在以12小时为周期在消耗IO。
追踪IO使用状况
先使用iotop来定位出错时刻是谁占用了大量IO:
python /sbin/iotop -bPto -n 86400 > iotop.log
上述命令以批处理的形式,每1秒一个输出,一共持续86400秒(24小时)。同样,并没有发现除了我们程序之外的可疑线程。
Iotop虽然是一个好工具,然而一个缺陷是并没有详细的文档说明它的工作原理。对于一个系统工具来说,原理性的文档还是很有必要的。在这种情况下,我们怀疑iotop并不能真实的反映进程的IO使用状况。为了再次确认,我们采用SystemTap来统计IO调用。下面是改良过的iotop.stp:
global count_stacks
global size_stacks
g