svr雪崩问题重现和特性分析过程

 

 

 前言

新上线的一个中转server出现雪崩，整个业务都受到了影响，从业务侧看监控日志，基本上是发往该中转server的全部请求都未能正确处理返回，业务几乎处于不可用状态，事后经过尝试问题重现，分析出雪崩发生的原因。

本文将分享出整个问题定位的思路和技术手段，让大家对svr的特性有更进一步的认识，从而在以后的实际开发和运营工作中可以避免重复踩到同一颗地雷。

 

问题重现出来就解决了一半

先来看下我们的中转server所扮演的角色，如下图：

                           

   中转server分析各个业务发过来的各个请求，然后自己封装成第三方server需要的格式发送过去，这里中转server和第三方server各有几台做容灾和负载均衡，图中未体现出来，不存在单点故障。这里中转server在接入层使用的svr，默认是同步通讯方式，即业务发过来一个请求，中转server要从第三方得到结果并发送给业务方之后才能处理下一个业务请求。

服务几乎不可用有以下几种可能：

1.       server进程挂掉或者不停的core。

2.       业务端到中转server网络不可用或者时延过大。

3.       中转server到第三方server网络不可用或者时延过大。

4.       业务端到中转server的访问量突然飙升，导致处理不过来。

1和2已经通过现场排除，3和4由于事故发生时时延和访问量监控不到位无法确认，但我们可以从3和4提取出来一个共性，那就是中转server当时的处理能力无法匹配访问量的需求了(时延过大降低了server的处理能力)。

我们可以由以上的推断建立如下多线程对单进程的测试模型:

                            

 

需要说明的是，在测试的时候一定不要对现网造成过大影响，所以做性能测试的时候一般都需要打桩。我这里没有打桩，采取的策略是修改中转server的代码，每个请求处理里面额外休眠20ms来降低server的处理能力，即模拟了网络延时的可能，同时又不会对现网造成压力（单进程）。

现在我们可以初步评估一下server的处理能力，中转server到第三方server之间双向处理完毕花费平均时延在5ms之内，加上我们固定休眠的20ms，中转server处理一个请求花费时延在20-25ms之间，每秒钟可以处理请求40-50个之间。

 

客户端程序代码省略，下面只给出其主要逻辑:

1. 客户端多线程测试程序也是采取的同步通讯的方式，即每个线程都是收到中转server对上一个请求的处理结果后才继续发送下一个请求给中转server。

2. 客户端程序访问中转server的超时时间设置为1000毫秒。

3. 客户端输入参数代表工作线程数，另外还有一个单独的线程每隔5秒钟打印统计信息出来，统计信息格式:

total error count:错误总数(最近五秒钟内错误总数)，total count:发送请求总数(最近五秒钟内发送请求总数)， 日期时间

 

万事俱备，下面就开始我们的重现之旅吧。

首先，我们开启30个线程来进行测试，下图为测试结果：

 

由上图可以看到，每五秒钟客户端发送请求在178个左右，并且中转server全部都成功处理了，每秒钟大概处理178/5=35.6个请求，考虑到客户端和中转server之间的时延以及中转server本身的逻辑处理，与理论应该是相符的。

然后我们把线程数调到40（随着线程数的增加，并发量也进一步增大，会逐渐超过单进程中转server的处理能力），来看测试结果：

 

测试结果显示，客户端每秒钟发送200/5=40个请求，刚好等于线程数，并且全部都返回错误，strace跟踪进去可以看到，客户端全部超时返回了，问题已经重现出来，服务完全处于不可用的状态，也就是雪崩了。

是什么原因导致了不可思议的现象？

我们只是把并发量增加为稍微超过中转server单进程的处理能力，为什么会导致100%的超时出错返回呢？我们在客户端机器上抓包发现所有的请求发过去之后，服务端都未返回任何处理结果，下面抽取其中一个连接作为示例：

 

 

可以看到tcp的三包握手完成后，client发了一个请求过去，中转server端的tcp/ip协议栈回复了一个ack，之后就一直没有返回应用层的处理结果，直到客户端超时主动关闭发送了FIN包。

让我们来看看中转server进程是否出了问题，有没有可能出现阻塞之类的现象呢？后台的监控日志显示，在过去的二十几秒内，成功处理了600多个请求，时延均正常，说明到第三方server也没有任何问题。那问题到底出现在哪里？明明成功处理了这么多请求，为什么没有发送给客户端呢？同时还发现有比较多的svr proxy进程的错误日志：

 

 

为什么会批量发送出错呢？结合我们在客户端抓包的结果，再根据sendto的错误返回值-20000，可以确定的是svr proxy进程在尝试发送处理结果给客户端时，却发现连接已经关闭了。那么现在存在两种可能：

1. 在worker单进程开始处理某个请求的时候，连接还没有关闭，但等处理完毕之后要发送回客户端的时候就发现连接超时关闭了。
2. 在worker单进程开始处理某个请求的时候，根本就没有去判断连接是否已经关闭，管它呢，闷头干活吧。

第一种可能是有一定概率会出现的，但是100%的都是这种情况显然有点令人难以置信，那么第二种情况有没有可能呢？

下面我们就来做一个实验来验证是否存在第二种情况，更改我们的客户端程序如下：

1. 只开两个工作线程。

2.第一个线程对xxx进行查询，客户端到中转server的超时时间为300ms。

3. 第二个线程对xxx进行查询，客户端到中转server的超时时间为10ms，并且为了便于观察，在发送请求之前先休眠10ms。

 

下面是我对中转server的proxy进程strace的结果:

 

可以看到proxy进程一前一后收到了对xxx（对应客户端第一个线程）和xxx（对应客户端第二个线程）的查询请求，并且在37分21秒519296微秒的时候客户端主动关闭了连接(10ms的超时时间，recv返回为0)。

 

  同时在另外一个终端窗口中，我对worker进程也进行了strace跟踪:

  

 

 

可以看到的是在21秒收到超时后，仍旧在22秒处理xxx这个号码，说明work进程在处理一个请求时，根本不管这个请求对应的连接是否已经关闭了。至此，问题已经很清楚了，我们可以得出结论：

 

1.当访问量飙升时，超过了svr的work进程的处理能力，导致大量的client请求被积压，并且在work进程去处理这些请求之前，客户端因为超时主动关闭了连接。

2.work进程一直在处理这些已经被client主动关闭的请求，并且从业务本身来看一直都处于比较正常的状态，只是在发送给client处理结果的时候返回错误，因为这个连接已经关闭了。

3.新来的client请求由于前面还有很多积压的过期请求还未处理，一直在等待，直至超时。

svr的work进程一直在“努力工作”，只是一直在做无用功，所承载的整个业务基本上处于瘫痪状态。

svr本身对雪崩的处理

其实S++本身从诞生开始就有一个msg_timeout参数来对过期包进行处理，只不过知道的人非常少，手册上也没有说明。在work进程的配置文件里，如下图:

 

如图中所示，过期时间被我们设置为1000ms。

msg_timeout应该设置为多少才合理呢？假设客户端超时时间为CT，客户端到server的单向时间为ST，server本身处理耗费时间RT，个人觉得msg_timeout应该设置为(CT-2*ST-RT)比较合理，在本文所做验证的实例中，CT为1000ms，RT约为22ms，ST约为1ms，我们把msg_timeout设置为976ms来进行测试，下面是测试结果：

以上测试我们开了40个线程，可以看出错误率在40%-50%之间(加msg_timeout之前是100%的错误率)，避免了服务100%不可用的状况。

下面是开20个线程的测试结果，证明在正常访问量的情况下这个msg_timeout值并未引起不应该的错误率。

 

由以上的实验我们可以看出，msg_timeout确实可以避免服务完全瘫痪的情况发生，但40%-50%的错误率让人无法接受，因此可以得出结论，msg_timeout机制也只能保证服务部分可用，无法完美解决问题，

值得一提的是，msg_timeout机制还有一个好处就是当流量恢复正常值后，快速恢复正常服务，试想在没有设置msg_timeout的情况下，只是持续短短几分钟的流量飙升都可能导致大量过期请求积压起来，即使流量恢复正常后，仍然会有大量的新请求会超时，这种状况会持续几十分钟甚至几个小时之久。msg_timeout机制却能一次性清除所有堆积的过期请求，使新请求得到及时处理，服务回到正常水平。

当然最合理的解决方案还是在proxy进程收到client端的关闭FIN包时，就把排队等待处理中的该连接对应的请求给淘汰掉，但目前svr的实现机制做到这一点会花费比较大的代价，期待新版svr能够完美解决这一问题。