服务超时问题

背景

上游一个服务在调用我们服务的时候突然出现了大量的超时。首先怀疑的是docker机器又挂掉了，然后看了下服务的调用量监控,如下图。

从图中可以看出服务是在某个时间点突然没有任何流量（或者是服务本身问题导致不能上报监控指标）了。

服务之间是通过thrift进行通信的，thrift server的工作模式为TThreadedSelectorServer。

问题排查

首先是登录到服务器上验证docker是否正常或者服务是否存活。随机找了几台服务节点，发现docker和服务进程都存活着，说明可能是服务本身出问题了。

1. 使用tail -f error.log查看服务的错误日志，观察到一直在出现大量的异常。
   而且这个异常的出现时间点和监控出现异常的时间点相吻合。这会导致响应客户端请求的时间增长，导致客户端请求超时从而关闭连接。

java.util.NoSuchElementException: Timeout waiting for idle object
at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:448)
at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:362)

2. 通过 netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}' 查看对应端口的网络连接情况，单台服务器上有八万多个close_wait 连接。
   
   查看tcp状态转换图可知客户端一直大量的新建连接和关闭连接，并且服务端没来得及处理关闭连接事件(调用close()方法)导致服务端出现了大量的close_wait。

大量close_wait造成的影响

由于close_wait是系统层面的问题，比问题1容易定位些，所以先分析下问题2。

8万的close_wait连接说明服务进程中至少同时接收了8万个客户端的连接，其能造成的影响大致有以下几点：

1. 连接不停的创建和关闭，会增大创建tcp连接的耗时
2. 过多的tcp连接会占用一定的内存，如果还在服务器内存不够时，还会压垮整个服务器。单个连接占用情况可参考文章
3. 服务处理tcp连接的线程模型会决定此服务是否能处理这么多的连接。由于服务使用的是nio来处理网络连接，处理接收连接和关闭连接事件是在单独的线程池，与处理业务逻辑的请求是隔离的，所以这个问题的只是影响了网络连接这块的，当前的这个服务来说不算特别大。

连接池问题

由于当时的现场信息保留不完整，现在推测一下问题产生的原因。

java.util.NoSuchElementException: Timeout waiting for idle object是因为在从连接池里取新redis连接超时导致的。导致这个问题可能会有以下原因：

1. 连接在用完之后没有及时释放，一直没有可用连接
2. redis集群突然出现问题，请求耗时增大、建立连接时间过长、网络抖动使请求总耗时增加
3. 并发过大导致排队时间过长

当前的服务运行已经超过一个月，这次是突然几十台节点同时出现问题，并且流量没有变化。因此基本上可以排除1、3，最可能的是使用的redis集群出现了问题。而在redis集群出现问题又会不会导致问题1、3发生，由于没有足够信息，现在很难下结论。

结论

看下当前服务的执行逻辑，来分析下连接池问题如何导致整个服务处于不可用的状态。

建立连接过程

处理请求流程图

上面这个流程图省略了业务处理逻辑，只展示了各个线程之间的交互关系。从流程图中很容易的可以看出在redis集群出问题时，服务中有两个逻辑漏洞：

1. 当等待可用连接步骤出现了问题时，会导致thrift-server线程池中积累大量任务
2. 并且在这个线程池中的任务会一直等待下去，不会被标记为超时

这就会导致了上游调用超时，并且后续的请求基本都会超时，这也就能解释为什么一个短暂的网络抖动导致上游持续超时。

解决方案

有了结论，找到解决方案就非常容易了。

快速解决方案

当前问题快速的解决方案是服务进行重启。

优化程序

不管是作为客户端还是服务端都需要设置一个服务熔断策略。服务在不可用的情况下，继续请求只会加大服务的负载，更难恢复，原因如下：

1. 客户端在访问某个服务时出现了大量的超时情况时下，再持续的创建新连接发送新请求，也会严重的拖累自身。
2. 服务端在发现服务基本不可用时，再继续接收新的业务逻辑请求时，会让本就超负荷运转的服务更难恢复过来。