携程一次 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  &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也没有任何问题。当然,这里提醒下,不要盲目的调整到很高的值,是否可以调整到这么高,还要结合各自服务器的配置以及业务场景。

【推荐阅读】

“携程技术”公众号
分享,交流,成长