携程一次 Dubbo 连接超时问题的排查
作者简介
顾海洋，携程框架架构研发部技术专家，负责携程分布式服务化领域的工作。目前主要负责 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: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
|
Backlog |
每秒并发建连数 |
SYN包被丢？ |
|
128 |
3000 |
无 |
|
128 |
5000 |
少量丢包 |
|
1024 |
5000 |
无 |
|
1024 |
10000 |
无 |
可以看到，对8C的机器backlog为128的情况下，在每秒5000建连的时候就会出现syn丢包。在调整到1024之后，即使10000也没有任何问题。当然，这里提醒下，不要盲目的调整到很高的值，是否可以调整到这么高，还要结合各自服务器的配置以及业务场景。
【推荐阅读】
-
携程容器偶发性超时问题案例分析
-
携程云原生基础设施演进之路
-
聊聊携程升级Dubbo的踩坑历程
-
携程的 Dubbo 之路
-
携程技术出书啦，点开有彩蛋~
“携程技术”公众号
分享，交流，成长
正文到此结束
- 本文标签： queue id 部署 云 端口 grep Netty 参数 lib 服务端 tk IBM SOA list client message 长连接 并发 tab js 调试 Docker Connection IOS MQ 缓存 源码 https UI 实例 推广工作 kk IO 注册中心 启动过程 ip 配置 CEO 同步 http NIO 专注 协议 shell apr TCP dubbo 推广 图片 高并发 服务器 tomcat cat 时间 开发 core Service 分布式 java db 线程 代码 操作系统 src
- 版权声明： 本文为互联网转载文章，出处已在文章中说明(部分除外)。如果侵权，请联系本站长删除，谢谢。
- 本文海报： 生成海报一 生成海报二
热门推荐
相关文章
近期评论
-
666
-
文章和留言都翻到11页了 没有OOM
-
-
朋友，翻页到11页，及以后，会出现OOM，无法访问
-
-
-
-
版本号是多少，你可以下载哪个代码仓库，jdk选1.8 直接跑就行
-
-
Loading...
![[HBLOG]公众号](https://www.liuhaihua.cn/img/qrcode_gzh.jpg)
