服务超时实战分析

开发服务的时候，经常发现客户端超时的情况，但是从服务端的日志来看又都比较正常，下面是我项目中遇到的一些不同的超时情况。

 

业务场景：

      基于一段长文本，划出文本中的内链

 

我主要遇到过如下三种场景的超时

1、客户端query太长

服务对这个query的处理消耗的时间比客户端设置的超时长，导致服务还没有把请求处理完毕，客户端就已经超时断开了

当时调用方反馈了超时情况后，我让他们把超时的query全部拿出来看了下，参数的长度长达几万个字符，而我们这种业务场景下服务对请求的处理时间基本和query长度是成正比的，由于他们设置的超时太短，从而导致超时

 

解决办法是：

       针对不同的业务场景要不同的处理。 

       我们的场景是：  其实调用方大量的请求都是重复的请求，我们对请求处理的结果他们并没有存储，这样导致每次用户访问同一个页面的时候，我们都要重复去计算内链。所以后来调用方做了两件事，第一是提高超时时间，第二对已经计算得到的结果进行存储，减少重复请求，第三对过长的文本进行截断或者分批请求

 

2、服务处理不过来了

调用方是通过nginx来访问的我们的服务，客户端报超时，但是nginx日志和我服务端日志都没有报超时

nginx记录的是它和我服务端通信的一个状态，即使客户端超时主动断开了与nginx的连接，只要nginx设置的超时时间比我服务的响应时间长，那么nginx那就不会记录超时，

由于客户端设置的超时是500ms，于是我统计了nginx上日志记录的我服务的响应时间超过500ms的，发现有300多个，那么很显然，这批请求肯定会导致客户端超时。 

 

现在说的这种场景其实跟1是一种情况。但是我想说的是当服务处理不过来的时候，大量的请求会处于等待状态，所以其实一个请求的时间主要就是消耗在等待被处理上，而不是真正的服务时间很长。这种情况下有一个比较明显的现象是，比如CPU的使用率到100%、或者是一些其他的资源到了瓶颈。

 

通过nginx日志可能也可以看出来，当nginx调用一个ip的时候，如果它没有响应，那么它会转成去请求另外一个ip，如果出现这种一个请求打到了多个机器上，然后结合一些资源使用率，基本可以断定服务现在已经处理不过来了

 

3、服务端记录日志耗时太长、磁盘IO到了瓶颈

现象：服务部署的四台机器中其中一台机器超时比较多

 

解决： 首先top看下这台机器上服务进程的资源使用情况

$top

top命令看了我的服务的CPU和内存使用率都很低，但是有一个比较显眼的是有一个进程消耗的CPU特别高，那个进程正在重建索引

重建索引会进行大量的写磁盘

 

用iostat看下磁盘使用情况

$iostat -d -x 1 100

 

得到如下结果：

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
sda               0.00     2.00    1.00    3.00    16.00    40.00    14.00     0.00    0.50   0.25   0.10
sdb               0.00    18.00  284.00   22.00 13040.00   824.00    45.31     0.55    1.81   0.26   7.90
sdc               0.00     0.00  203.00    0.00 10776.00     0.00    53.08     2.47   13.31   4.24  86.00
sdd               0.00     0.00  131.00    1.00  2872.00   256.00    23.70     1.86   14.23   2.10  27.70
sde               0.00     0.00  360.00    1.00  5760.00   256.00    16.66     4.75   13.22   2.71  97.70

我们的服务是部署在sdc盘的，服务会打日志在这块盘上，现在这块盘的使用率90%的以上，比较可能的原因是磁盘io被重建索引的服务占用，导致内链服务写日志速度慢，从而导致超时

 

4、服务内部调用某个远程接口超时

现象：下面是我代码中记录日志的方式

记录日志1
请求处理、调用远程thrift接口
记录日志2
获取TCP连接，从而拿到远程ip和端口
记录日志3

正常的请求会有上面的三个日志，但是异常超时的请求，只有1和2的日志，没有3

原因分析：观察了下，客户端报超时的query对应的日志1和日志2之间的时间戳的差值很大，长达几秒，而客户端设置的超时时间只有280ms而已，所以在执行到获取TCP连接时，其实此时客户端已经把连接断开了，所以这里获取TCP连接应该会报异常，导致记录日志3的代码不会实行。

 

5、服务内部读取Redis的io太多

加了日志后，观察了下代码每个阶段的耗时情况，发现在一个代码块耗时很严重，因为这里有大量的Redis的io。虽然Redis的速度很快，但是如果io次数太多，累加起来也会消耗很长的时间。

解决办法：把这些所有的请求能合并的尽量合并，用pipeline把多个类似请求做一个批处理，把多次io合并成一次io

 

6、TIME_WAIT导致

代码中需要调用一个thrift远程分词服务，这个服务正常的响应时间在几毫秒，但是在使用的过程中，发现这个服务经常超时，有的时候高达几秒甚至几十秒。 

分析：

首先我们对这个远程thrift服务进行了压测，发现问题的确可以复现，而且一个现象是随着压测的进行，客户端的TIME_WAIT一直增长，会达到几万个，我们知道TIME_WAIT是客户端的状态，一般是TCP连接需要经过2MSL的时间后会自动释放，但是因为这个服务的耗时很短，所以很快，可用的几万个端口都被用光，老的端口也得不到释放，就导致了超时问题。

解决思路：

a、修改客户端的系统参数

sysctl -w net.ipv4.tcp_tw_recycle=1 #及时回收
sysctl -w net.ipv4.tcp_tw_reuse=1   #tcp连接重用

让连接可被重用，并且及时回收

 

b、改用thrift长连接

需要维护一个thrift连接池，基本上就是自己构造一个连接池对象了，自己管理连接，用的时候就从里面取，用完了就放回去。