携程一次 Dubbo 连接超时问题的排查
作者简介
顾海洋,携程框架架构研发部技术专家,负责携程分布式服务化领域的工作。目前主要负责 Dubbo 在携程的二次开发和推广工作。
李伟,携程云平台技术专家,2012年加入携程,目前专注于云原生方向技术的研究和落地,先后参与负责过携程部署架构改造、接入层架构升级等项目的设计和推广。
工作中,常常会遇到连接超时的问题,一般都是先检查端口状态,然后再检查CPU、Memory、GC、Connection等机器指标是否正常。如果都在合理范围内就会怀疑到网络或者容器上,甩手丢给网络组同事去排查。
今天,我们想分享一个高并发场景导致的connect timeout,对原因以及过程的分析或许可以帮助大家从容地面对类似问题。
一、问题背景
携程度假事业部的某个核心服务在两个机房一共有80台机器,每台机器都是4C8G的docker容器。这个服务的调用方比较多,几十个调用方的机器加起来大概有1300多台。
SOA over CDubbo是将现有SOA框架的HTTP传输协议切换到TCP协议,能够解决长尾问题以及提供更好的稳定性。大概实现原理是,服务端通过CDubbo启动代理服务,客户端在服务发现后与服务端同步建立TCP长连接,请求也会在TCP通道传输。
但是,度假事业部的这个服务每次发布总是会有部分客户端报connect timeout,触发大面积的应用报警。
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端口的状态。
do
lsof -nPi | grep 20xxx
sleep 1
done
从结果中,可以看到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状态,没有任何客户端跟它连接。
java 24715 Tim 217u TCP *:20xxx (LISTEN)
之后,继续执行代码,Netty在socket的accept执行之后,就可以看到连接已经ESTABLISHED成功了。Netty在accept连接之后会注册到worker线程进行IO处理。
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 &1|grep -c 'Escapecharacter is'` echo$(date) "20xxx check result:" $t sleep0.005 done
从脚本的执行结果看到,容器内发起的连接有时也是会失败的,以下黄色高亮的0就是失败的连接。
同时,从服务端的抓包结果看到,也会有syn被丢弃的情况。
八、全连接队列满导致的SYN丢包
syn 包被操作系统丢弃,初步猜测是 syn queue 满了,通过 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是哪里来的呢?
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 50 *:20xxx *:*
然后看了下机器内核的somaxconn也远远超过50,难道50是应用层设置的?
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也没有任何问题。当然,这里提醒下,不要盲目的调整到很高的值,是否可以调整到这么高,还要结合各自服务器的配置以及业务场景。
【推荐阅读】
“携程技术”公众号
分享,交流,成长