SRE重案调查组 第五集 | 为什么我的服务器又双叒不响应了？！

这是本人发表在 eBay 微信公众号 eBay技术荟 上的 一系列文章, 原文地址如下. 编辑非常给力, 请查看原文, 这里只是供搜索引擎访问.
https://mp.weixin.qq.com/s/-CTHVLxgzTn79vOqEe_CQQ

如果原文由于某种原因不存在了, 请查看这个pdf 版本:SRE重案调查组 第五集 | 为什么我的服务器又双叒不响应了？！.pdf

导读

在SRE的日常工作中,经常会碰到很多典型问题。其中一种便是:为什么我的服务器不响应了? 

原因可能是服务器软件或硬件损坏,应用程序未启动,网络防火墙,服务器配置等基本的环境问题,也有可能是与应用程序关联比较紧密的代码问题。后者不易发现,又或是长期累积的结果,查起来不像环境问题那么直接。这里列举几个发生在生产环境的真实案例,希望对大家诊断类似的问题有所启发。

案例一：javaswift客户端代码的锅

某天,SRE的监控工具发现有些应用在熔断后端的某个服务,查看后端该服务后,发现它在不断地告警:异常检测工具显示其服务器忙碌线程数刷出了新高度。

该服务器的所有tomcat线程都忙起来了,达到了设置的上限(这里设置是100),可是CPU使用率却不完全匹配。CPU使用率和出错个数在忙绿线程数的爬升阶段,并没有表现出什么异常。而当到达上限一段时间之后,CPU使用率和出错数才出现了一些异常。如下图1所示:

服务器线程忙碌个数以及CPU使用率,出错数:

图1（点击查看大图）

再看该服务的tps,基本降到了0。也就是说，虽然有大量的请求连接进来,但是没有一个能正常完成。事实上，该服务已经不工作了,一旦连接数达到设置的上限(100),就不再增长。对于本来应该正常访问的客户端来说,绝大部分都无法访问该服务了,所以我们可以看到客户端基本对这个服务全部熔断了。此时,该服务基本不再响应新的请求。

那为什么会出现这种情况呢?到底是哪里出了问题?

为了查明真相,我们做了一个thread dump。从图2 thread dump可以明显看到:这些Tomcat线程都卡在了同一个地方:它们下一步都要访问swift存储,因此第一步就是要从连接后端swift的连接池中获得一个TCP连接,现在却都卡在从连接池获取连接这一步了。

如下图2所示,这个线程正试图从连接池租用连接,由于没有立马获得,正处于WAITING状态,等待获得连接。查看Tomcat的服务线程,基本都处于这个状态。

Thread dump片段,其中一个Tomcat守护线程正在等待获得连接:

图2（点击查看大图）

本来连接池中应该有足够的连接,可为什么又无法获得呢?

首先我们要怀疑,这个线程池中到底有没有连接?

正常情况下,如果没有连接,连接池会自动创建新的连接,不用等待。同时,通过Linux上的ss命令,我们能看到确实有正处于连接状态的TCP连接。那么可以基本确认连接池是有连接的。

如果有连接,这些连接又并非处于使用中,为什么等待线程无法获得呢?

为了进一步挖掘出这背后的原因,我们首先检查thread dump。但是通过关键字搜索,并没有发现有任何线程处于和后端swift存储通讯的读操作或写操作的过程中。

接着,我们对产生的heap dump分析,发现了更为奇怪的现象。这个应用与后端swift存储建立了25个TCP连接。从heap dump数据来看,这25个连接全部都已被租用,没有任何空闲连接。同时，等待队列里面还有241个线程正在等待获得连接。具体如下图3、4和5所示:

连接池里面已被租用的连接数是25:

图3（点击查看大图）

连接池里面空闲的连接数是0:

图4（点击查看大图）

连接池的等待队列里面等待的个数是241:

图5（点击查看大图）

这就更奇怪了,为什么这些连接被租用了,却没有看到被使用呢?这在逻辑上根本无法说通。

于是我们转而寻求其他方向。

经过一番查看，我们从出错日志中发现了一些从未出现过的出错信息，而且这些出错信息还是与javaswift客户端相关的。顺着这些出错日志,我们找到了这个类:

对这个类的代码进行仔细阅读,总觉得少了点什么。于是拿最新的开源版本和我们使用的做比较,发现使用的这个版本中有个明显的bug,而这个bug在官方开源版本中早已修复: 在捕获某些异常之后,应该手动释放连接,否则这些连接将一直被占用,无法被后续请求使用。

官方修复代码的对比:

图6（点击查看大图）

至此,SRE侦探已基本查明该问题:javaswift客户端正常情况下在连接池里建立25个连接,而连接通信过程却发生了某些异常。客户端在处理异常时,由于有缺陷的代码没有释放连接,导致连接池里面的连接被用光；以至于新的请求无法从连接池获得连接；最终导致服务器无法获得后端swift存储的连接,全部被卡住；最后发生了服务器不再响应的问题。

案例二 Timeout的锅

某日,监控平台上显示某个应用的平均并发处理线程数已经突破500,还在一直增加,而CPU使用率和内存使用率却没有明显增长。

这个神奇的应用顿时引起了SRE的注意。如下图7所示,从某个时间点开始,某些应用服务器的忙碌线程数呈直线上升趋势。

应用服务器忙碌线程数持续线性增加,每条曲线代表一个服务器的忙碌线程数:

图7

查看该应用代码,发现是一个流处理(Streaming)程序,使用的是Server Sent Events(SSE)技术,服务端持续产生流数据,客户端一旦建立连接,就会在连接内持续收到从服务端发过来的流数据。

由于该连接会保持一段时间,因此每个新请求都会占用一个连接和一个应用服务器服务线程。加上其CPU和内存使用率非常低,所以开发人员通过设置较高的应用服务器服务线程数来扩展处理能力。这看上去是一个不错的选择。

那到底是什么导致服务器忙碌线程数不断线性增加呢?

我们先用netstat命令查看了服务器维持的TCP连接,发现尽管这里某个服务器显示为已经有500+应用服务线程在忙碌,可是只看到仅有的几个客户端发来的TCP连接(这里其实是客户端通过前端负载均衡服务器发过来的连接)。

为什么会出现这么矛盾的现象呢?

理论上如果Tomcat服务器有一个正在忙碌的线程,就说明正在处理一个客户请求,那么就会有一个客户端发过来的TCP连接。可是现实情况却不吻合:应用服务器正在忙碌工作的线程数很多,而客户端正在通讯的连接却很少。

进一步查看某台Tomcat服务器的thread dump,我们发现了有趣的症状：绝大多数Tomcat服务器线程竟都阻塞在一个getNextEvent()方法上面，如图8所示。

Thread dump片段,这个线程正阻塞在getNextEvent方法上,共有515个线程都在执行这个方法:

图8（点击查看大图)

这个getNextEvent()到底是做什么用的?为什么有这么多的线程阻塞在这里呢?

通过查看源代码和Server Sent Events的运行机制,我们了解到：Server Sent Events在后端不断地产生事件,每产生一个便发给客户端一个,然后通过getNextEvent()等待下一个事件,这里的等待是通过BlockingDeque实现的。如果等到一个新事件,就立马发给客户端,然后进入下一个等待,如此循环往复。

同时,它还有一个最长持续等待时间(timeout),一旦超过这个时间,就会抛出异常,结束长连接。鉴于服务器有如此之多的线程持续等在getNextEvent()上面,我们查看了它的超时时间设置,发现其时间设置竟长达86400秒,也就是说它为了等待下一个事件,可以最长等待24小时。

这里的设置忽略了一个常见事实,即：客户端通常不会设置这么长的超时等待时间,往往只设置30秒以内的超时时间。针对该服务的客户端,我们查看了设置,发现确实只设定了20秒。

那么这个问题就很容易理解了:服务端在某些时候需要较长的时间去等待下一个事件,可是客户端却因为超时而断掉了TCP连接。这时服务端的操作系统层面也会结束该TCP连接,而服务端的Tomcat处理线程因为一直阻塞在getNextEvent()方法上面,无法退出,也不知道客户端已经断开了连接。

这导致我们看到一个极其不和谐的现象:由客户端发过来的正在通信的TCP连接非常之少,并且这些连接都是在最近20秒内新建立的,可是服务端却显示应用服务器有大量的忙碌线程。

于是线性增长问题便很容易理解了。根据SSE的机制,客户端在断掉连接后,会自动尝试建立一个新的连接,所以更能还原这个场景的描述是:

客户端发起一个连接,服务端一个线程去响应,之后阻塞在getNextEvent方法上,20秒超时之后,客户端先断开连接,然后又新建一个TCP连接,导致服务端连接不断线性增加。

修复其实很简单,根据业务需要,把服务端getNextEvent()的等待下一个事件的最长超时时间设置在一个合理的较短时间内即可。

SRE工作常常如此，最后一步的修复看似简单无比，但这分析问题、解决问题的过程却着实艰辛而漫长。不过当“案件”逐步破解，真相水落石出之时，我们便觉得之前的种种辛苦也都值得了。

案例三：同步锁的锅

某日,我们看到有个应用的忙碌线程数曲线不断波动，就像过山车一样,有时候是个位数字,有时候升到40又降下来，如图9所示。

要知道，一般的服务器忙碌线程数都稳定在一个特定的值附近,这么大的起伏，看上去着实奇怪。除此之外，40还是这个服务器设置的最大值,一旦达到40,新的请求就无法进来。

应用服务器的忙碌线程数:

图9（点击查看大图）

我们观察了该应用请求进来的情况,发现进来的连接数随着时间基本匀速到来,当到达40的上限时,新请求就无法再进来了。然而在请求完成的时间点上,我们观察到有些波动,也就是说,这些请求随着时间顺序进来,却在固定的时间点上相继很快完成,这与上面的应用服务器忙碌线程数的曲线是吻合的。

那么是什么导致整个现象产生的呢? SRE侦探着手展开调查。

在服务器的thread dump中,我们发现了一些线索。在某些时间点上,很多应用服务器的忙碌线程都在等待一把锁,如图10所示。

Thread dump片段,某应用服务器线程正在等待一把锁:

图10（点击查看大图）

然而这把锁却被另外一个访问数据库的线程所拥有,而这个访问数据库的线程又在执行一个耗时比较长的操作,导致其他等待这把锁的线程只能阻塞在那里，如图11所示。

Thread dump片段,某个线程拥有了锁,在做一个耗时操作:

图11（点击查看大图）

一旦该访问数据库耗时较长的线程释放锁,其他线程就相继得到锁,然后就能很快完成请求。所以说，一旦这种需要访问较长数据库的请求进来,并且得到锁,它就会阻塞其他线程,一旦释放,其他线程就能很快完成请求。这就解释了上面过山车形状的曲线。

问题的根结出在这个锁上面,从业务逻辑角度去理清对于不同的请求是否需要这把锁,以及如何使用这把锁,就很容易解决这个问题。

案例四：HashMap的锅

某日,监控平台上显示有个应用的某台服务器CPU使用率已经达到100%,同时忙绿线程数已经到达上限。这台服务器已经不能再接受新的连接请求，如图12所示。
服务器CPU使用率100%:

图12

赶在自动运维机器人对它重启之前,我们做了thread dump和heap dump。从图13的thread dump来看,基本能找到问题所在:

Thread dump片段,显示有40个线程都在执行HashMap.getEntry()方法:

图13（点击查看大图）

这里显示有40个线程都运行在HashMap.getEntry()方法上面,根据我们的经验,基本是多线程并发访问同一个线程不安全的HashMap所致。针对heap dump分析,确认这些线程访问的是同一个HashMap,并且里面有个通过next引用串起来的死循环。

一旦一个线程陷入HashMap的死循环,就不可能从中退出来,最终导致所有要访问这个HashMap特定桶的线程都陷入进去,没有任何空闲线程能处理新的请求,服务器不再响应新请求。

针对该类问题,通常都是有人不恰当地对多线程并发情况使用了HashMap。使用其他线程安全的Map实现基本都能解决这类问题。

总结

服务器端不响应,往往是环境问题引起的,也有部分是程序代码问题导致的。如果检查发现应用所处环境都没有问题,可以从以下方向入手，来查验是不是代码的问题。

1）应用服务器忙碌线程的个数及变化;

2）Thread dump里应用服务器的线程运行状况;

3）同步锁的使用情况;

4）来自客户端请求的TCP连接状态。

通过对以上几方面的检查,我们基本就能获得一些有用的线索，从而找出服务器不响应的元凶。