java中连接服务端接口超时,服务器诡异的请求超时问题

前些日子，监控显示线上偶尔发生请求两秒超时的情况。解决这个问题前前后后花了不少时间，也走了一些弯路。这里记录下来备忘。

前期分析

首先需要了解一下我们的服务：

我们的服务是一组无状态的前端服务器加上有状态的后端存储层。

这些服务都部署在腾讯云黑石服务器上面。

第一件事是要定位问题出现在前端还是后端。通过日志，我们发现在出错时间段里，每个前端服务器都有报错，并且出错请求都是发往同一后端服务器的。由此可见，问题出现在后端服务上。

接下来，需要分析出错的特征。通过日志发现错误都是因为前端两秒超时导致，而后端在前端超时之后事实上是完成了请求。因为是存储服务，我们自然在第一时间就查看了磁盘的情况。果然，在出错时，磁盘的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