作者简介
顾海洋，携程框架架构研发部技术专家，负责携程分布式服务化领域的工作。目前主要负责 Dubbo 在携程的二次开发和推广工作。
李伟，携程云平台技术专家，2012年加入携程，目前专注于云原生方向技术的研究和落地，先后参与负责过携程部署架构改造、接入层架构升级等项目的设计和推广。
工作中，常常会遇到连接超时的问题，一般都是先检查端口状态，然后再检查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:portat 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}dolsof -nPi | grep 20xxxsleep 1done |
|---|
从结果中，可以看到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 20xxxjava 24715 Tim 217u TCP *:20xxx (LISTEN) |
|---|
之后，继续执行代码，Netty在socket的accept执行之后，就可以看到连接已经ESTABLISHED成功了。Netty在accept连接之后会注册到worker线程进行IO处理。
$ lsof -nPi | grep 20xxxjava 24715 Tim 0t0 TCP 10.xx.xx.1:20xxx->10.xx.xx.139:12918 (ESTABLISHED)java 24715 Tim 0t0 TCP *:20xxx (LISTEN) |
|---|
这就证明连接失败不是应用层丢掉的，肯定是操作系统层面的问题了，那么容器内的连接是否会成功呢？
七、从容器内发起的连接是否能成功
通过重启服务的时候，脚本不停的对服务端端口发起连接，看看是否会有失败的情况。
代码语言：javascript复制#!/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 -s3220 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
Backlog | 每秒并发建连数 | SYN包被丢？ |
|---|---|---|
128 | 3000 | 无 |
128 | 5000 | 少量丢包 |
1024 | 5000 | 无 |
1024 | 10000 | 无 |
可以看到，对8C的机器backlog为128的情况下，在每秒5000建连的时候就会出现syn丢包。在调整到1024之后，即使10000也没有任何问题。当然，这里提醒下，不要盲目的调整到很高的值，是否可以调整到这么高，还要结合各自服务器的配置以及业务场景。
