携程Dubbo连接超时问题的排查

工作中，常常会遇到连接超时的问题，一般都是先检查端口状态，然后再检查CPU、Memory、GC、Connection等机器指标是否正常。如果都在合理范围内就会怀疑到网络或者容器上，甩手丢给网络组同事去排查。

今天，我们想分享一个高并发场景导致的connect timeout，对原因以及过程的分析或许可以帮助大家从容地面对类似问题。

一、问题背景

携程度假事业部的某个核心服务在两个机房一共有80台机器，每台机器都是4C8G的docker容器。这个服务的调用方比较多，几十个调用方的机器加起来大概有1300多台。

SOA over CDubbo是将现有SOA框架的HTTP传输协议切换到TCP协议，能够解决长尾问题以及提供更好的稳定性。大概实现原理是，服务端通过CDubbo启动代理服务，客户端在服务发现后与服务端同步建立TCP长连接，请求也会在TCP通道传输。

但是，度假事业部的这个服务每次发布总是会有部分客户端报connect timeout，触发大面积的应用报警。

com.alibaba.dubbo.rpc.RpcException: Fail to create remoting client for service(dubbo://ip:port/bridgeService)  failed to connect to server /ip:port, error message is:connection timed out:  /ip:port
at  com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol.initClient(DubboProtocol.java:364)
at  com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol.getSharedClient(DubboProtocol.java:329)
at  com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol.getClients(DubboProtocol.java:306)
at  com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol.refer(DubboProtocol.java:288)

从日志分析，是CDubbo代理服务TCP连接失败，还好当初设计的时候考虑到降级机制，没有影响到用户流量。有同事提到既然没有影响，是否可以考虑把日志降级。这么诡异的问题，不知道是否会有其他层面的问题需要去优化的呢，作为执着的技术人员，我们决定排查到底。

二、服务的端口是否异步打开

调用方的每台机器都要跟160个服务端实例建立连接，但是客户端看到的报错量只有几个。所以，最开始怀疑客户端的连接发到服务端，但是端口没有来得及打开，导致少量的连接失败了。

翻了下SOA框架在处理实例注册的代码，启动CDubbo代理是在注册之前，而且是同步启动的，这样的话就否定了端口没打开的可能。

三、怀疑注册中心推送出现了问题

正常情况下的注册发现机制是在服务端健康检查通过后，再把实例推送到客户端。是否注册中心推送出了问题，服务没注册完就把实例推送到客户端了？或者，客户端实例缓存出现问题导致的呢？

这类问题还是要从日志入手，翻了下Dubbo的代码，如果Netty打开端口之后，是会记录端口打开时间的。

从日志系统可以看到端口是在16:57:19就已经被打开了。

客户端在16:57:51发起的连接居然失败了，这个时候端口肯定是已经被打开了。从这个层面推断注册中心或者缓存机制应该是没有问题的。

那么，是否端口打开后又被莫名其妙的关闭了呢？

四、怀疑端口打开后又被莫名其妙的关闭

不确定是否服务启动后，会有某些未知的场景触发端口被莫名其妙的关闭。于是，在本地模拟服务启动，启动过程中通过shell脚本不停的打印端口的状态。

通过以下这段脚本，每1s就会打印一次20xxx端口的状态。

for i in {1..1000}
do
lsof -nPi | grep 20xxx
sleep 1
done

从结果中，可以看到20xxx端口一直处于listen状态，也就是正常情况下并不会被莫名其妙的关闭。

TCP *:20xxx (LISTEN)

五、增加连接被accept的日志

Dubbo已经打印了前面看到的端口打开的日志，如果再能够看到服务端连接被accept的情况就好了。

继续翻了Dubbo的代码，对Netty3的版本来说，连接被accept之后会执行channelConnected的。那么，只要在这里加点日志，就可以知道端口什么时候被打开，以及连接什么时候进来的了。

以下是基于Dubbo 2.5.10版本增加的日志。

业务同事帮忙升级了版本之后，服务端在16:57:51:394已经有连接被accept了，连接报错时间是16:57:51:527，也就是accept连接过程中只有一部分被拒绝了。

那么，是没有收到这个连接的syn，还是把syn给丢弃了呢，必须要抓包看看了。

六、服务端的TCP抓包

正常情况下，需要服务端和客户端同时抓包才有意义。但是，客户端数量实在太多，也不知道哪台机器会报超时，两端一起抓的难度有点打，所以决定先只抓服务端试试。

首先摘掉服务的流量，然后在Tomcat重启的过程中抓TCPdump。从TCP dump的结果中可以看到，服务端有一阵子收到了TCP的syn，但是全部没有回ack。可是HTTP的syn却正常的回复了syn+ack，难道是应用层把syn包给丢了？

没有回syn+ack是谁的问题呢，Netty丢掉的吗？还是操作系统呢？为此，我们做了个小实验。

小实验：

如果是应用层丢掉的，那么肯定要从Netty的入口处就调试代码。Netty3的NioServerBoss收到请求，会在以下箭头2处对连接进行accept，所以计划在1处打上断点。

启动服务端后，再启动客户端，连接进来的时候的确会被箭头1处block住。

通过TCP抓包发现在accept之前就已经回复syn+ack给客户端了。

这个时候，顺便看了下本机的20xxx端口情况，只有一个listen状态，没有任何客户端跟它连接。

$ lsof -nPi | grep 20xxx
java  24715  Tim  217u  TCP  *:20xxx (LISTEN)

之后，继续执行代码，Netty在socket的accept执行之后，就可以看到连接已经ESTABLISHED成功了。Netty在accept连接之后会注册到worker线程进行IO处理。

$ lsof -nPi | grep 20xxx
java   24715  Tim  0t0  TCP  10.xx.xx.1:20xxx->10.xx.xx.139:12918 (ESTABLISHED)
java   24715  Tim  0t0  TCP  *:20xxx (LISTEN)

这就证明连接失败不是应用层丢掉的，肯定是操作系统层面的问题了，那么容器内的连接是否会成功呢？

七、从容器内发起的连接是否能成功

通过重启服务的时候，脚本不停的对服务端端口发起连接，看看是否会有失败的情况。

#!/bin/bash
for i in`seq 1 3600`
do
t=`timeout0.1 telnet localhost 20xxx  </dev/null 2>&1|grep -c 'Escapecharacter is'`
echo$(date) "20xxx check result:" $t
sleep0.005
done

从脚本的执行结果看到，容器内发起的连接有时也是会失败的，以下黄色高亮的0就是失败的连接。

同时，从服务端的抓包结果看到，也会有syn被丢弃的情况。

八、全连接队列满导致的SYN丢包

syn 包被操作系统丢弃，初步猜测是 syn queue 满了，通过 netstat -s 查看队列的情况。

$ netstat -s
3220 times the listen queue of a socket  overflowed 
3220 SYNs to LISTEN sockets dropped

问题的原因基本找到了，可是导致syn被丢弃的原因还是不知道，这里我们先复习下三次握手的整个过程。

上图结合三次握手来说：

1、客户端使用connect()向服务端发起连接请求（发送syn包），此时客户端的TCP的状态为SYN_SENT；

2、服务端在收到syn包后，将TCP相关信息放到syn queue中，同时向客户端发送syn+ack，服务端TCP的状态为SYN_RCVD；

3、客户端收到服务端的syn+ack后，向服务端发送ack，此时客户端的TCP的状态为ESTABLISHED。服务端收到ack确认后，从synqueue里将TCP信息取出，并放到accept queue中，此时服务端的TCP的状态为ESTABLISHED。

我们大概了解了syn queue和accept queue的过程，那再看上面的问题，overflowed代表accept queue溢出，dropped代表syn queue溢出，那么3220 SYNs to LISTEN socketsdropped，这个就是代表syn queue溢出吗？

其实并不是，我们翻看了源码：

可以看到overflow的时候TCP dropped也会增加，也就是dropped一定大于等于overflowed。但是结果显示overflowed和dropped是一样的（都是3220），只能说明accept queue溢出了，而syn queue溢出为0（3220-3220=0）。

从上图的syn queue和accept queue的设计，accept queue满了应该不影响syn响应，即不影响三次握手。

带着这个疑问我们再次翻看了内核源码：

可以看到建连接的时候，会判断accept queue，如果acceptqueue满了，就会drop，即把这个syn包丢掉了。

九、全连接队列怎么调整？

我们再看下服务器的实际情况，通过ss -lnt查看当前20xxx端口的accept queue只有50个，这个50是哪里来的呢？

$ ss -lnt 
State Recv-Q Send-Q Local  Address:Port Peer Address:Port 
LISTEN 0 50 *:20xxx *:*

然后看了下机器内核的somaxconn也远远超过50，难道50是应用层设置的？

$ cat  /proc/sys/net/core/somaxconn
 128

Accept queue的大小取决于：min(backlog, somaxconn)，backlog是在socket创建的时候传入的，somaxconn是一个内核级别的系统参数。

Syn queue的大小取决于：max(64,tcp_max_syn_backlog)，不同版本的os会有些差异。

再研究下Netty的默认值，可以发现Netty3初始化的时候backlog只有50个，Netty4已经默认升到1024了。

业务换了新的包，重新发布后发现accept queue变成了128，服务端syn被丢弃的问题已经没有了，客户端连接也不再报错。

在应用启动时间，通过shell脚本打印队列大小，从图片中可以看到，最大queue已经到了101，所以之前默认的50个肯定是要超了。

从这个截图，也可以知道为啥前面提到的HTTP请求没有syn丢包了。因为Tomcat已经设置了backlog为128，而且HTTP的连接是lazy的。但是，我们对TCP连接的初始化并不是lazy的，所以在高并发的场景下会出现accept queue满的情况。

十、调整backlog到底有多大效果？

针对这个问题，我们还专门做了个试验了下，从实验结果看调整带来的效果还是比较明显的。

服务端：1台8C的物理机器

客户端：10台4C的docker

可以看到，对8C的机器backlog为128的情况下，在每秒5000建连的时候就会出现syn丢包。在调整到1024之后，即使10000也没有任何问题。当然，这里提醒下，不要盲目的调整到很高的值，是否可以调整到这么高，还要结合各自服务器的配置以及业务场景。

作者介绍：

顾海洋，携程框架架构研发部技术专家，负责携程分布式服务化领域的工作。目前主要负责 Dubbo 在携程的二次开发和推广工作。

李伟，携程云平台技术专家，2012年加入携程，目前专注于云原生方向技术的研究和落地，先后参与负责过携程部署架构改造、接入层架构升级等项目的设计和推广。