Categories
程式開發

攜程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連接超時問題的排查 1

三、懷疑註冊中心推送出現了問題

正常情況下的註冊發現機制是在服務端健康檢查通過後,再把實例推送到客戶端。是否註冊中心推送出了問題,服務沒註冊完就把實例推送到客戶端了?或者,客戶端實例緩存出現問題導致的呢?

這類問題還是要從日誌入手,翻了下Dubbo的代碼,如果Netty打開端口之後,是會記錄端口打開時間的。

攜程Dubbo連接超時問題的排查 2

從日誌系統可以看到端口是在16:57:19就已經被打開了。

攜程Dubbo連接超時問題的排查 3

客戶端在16:57:51發起的連接居然失敗了,這個時候端口肯定是已經被打開了。從這個層面推斷註冊中心或者緩存機制應該是沒有問題的。

攜程Dubbo連接超時問題的排查 4

那麼,是否端口打開後又被莫名其妙的關閉了呢?

四、懷疑端口打開後又被莫名其妙的關閉

不確定是否服務啟動後,會有某些未知的場景觸發端口被莫名其妙的關閉。於是,在本地模擬服務啟動,啟動過程中通過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版本增加的日誌。

攜程Dubbo連接超時問題的排查 5

業務同事幫忙升級了版本之後,服務端在16:57:51:394已經有連接被accept了,連接報錯時間是16:57:51:527,也就是accept連接過程中只有一部分被拒絕了。

攜程Dubbo連接超時問題的排查 6

那麼,是沒有收到這個連接的syn,還是把syn給丟棄了呢,必須要抓包看看了。

六、服務端的TCP抓包

正常情況下,需要服務端和客戶端同時抓包才有意義。但是,客戶端數量實在太多,也不知道哪台機器會報超時,兩端一起抓的難度有點打,所以決定先只抓服務端試試。

首先摘掉服務的流量,然後在Tomcat重啟的過程中抓TCPdump。從TCP dump的結果中可以看到,服務端有一陣子收到了TCP的syn,但是全部沒有回ack。可是HTTP的syn卻正常的回復了syn+ack,難道是應用層把syn包給丟了?

攜程Dubbo連接超時問題的排查 7

沒有回syn+ack是誰的問題呢,Netty丟掉的嗎?還是操作系統呢?為此,我們做了個小實驗。

小實驗

如果是應用層丟掉的,那麼肯定要從Netty的入口處就調試代碼。 Netty3的NioServerBoss收到請求,會在以下箭頭2處對連接進行accept,所以計劃在1處打上斷點。

啟動服務端后,再啟動客戶端,連接進來的時候的確會被箭頭1處block住。

攜程Dubbo連接超時問題的排查 8

通過TCP抓包發現在accept之前就已經回复syn+ack給客戶端了。

攜程Dubbo連接超時問題的排查 9

這個時候,順便看了下本機的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就是失敗的連接。

攜程Dubbo連接超時問題的排查 10

同時,從服務端的抓包結果看到,也會有syn被丟棄的情況。

攜程Dubbo連接超時問題的排查 11

八、全連接隊列滿導致的SYN丟包

syn 包被操作系統丟棄,初步猜測是 syn queue 滿了,通過 netstat -s 查看隊列的情況。

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

問題的原因基本找到了,可是導致syn被丟棄的原因還是不知道,這裡我們先複習下三次握手的整個過程。

攜程Dubbo連接超時問題的排查 12

上圖結合三次握手來說:

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溢出嗎?

其實並不是,我們翻看了源碼:

攜程Dubbo連接超時問題的排查 13

可以看到overflow的時候TCP dropped也會增加,也就是dropped一定大於等於overflowed。但是結果顯示overflowed和dropped是一樣的(都是3220),只能說明accept queue溢出了,而syn queue溢出為0(3220-3220=0)。

從上圖的syn queue和accept queue的設計,accept queue滿了應該不影響syn響應,即不影響三次握手。

帶著這個疑問我們再次翻看了內核源碼:

攜程Dubbo連接超時問題的排查 14

可以看到建連接的時候,會判斷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了。

攜程Dubbo連接超時問題的排查 15

業務換了新的包,重新發布後發現accept queue變成了128,服務端syn被丟棄的問題已經沒有了,客戶端連接也不再報錯。

在應用啟動時間,通過shell腳本打印隊列大小,從圖片中可以看到,最大queue已經到了101,所以之前默認的50個肯定是要超了。

攜程Dubbo連接超時問題的排查 16

從這個截圖,也可以知道為啥前面提到的HTTP請求沒有syn丟包了。因為Tomcat已經設置了backlog為128,而且HTTP的連接是lazy的。但是,我們對TCP連接的初始化並不是lazy的,所以在高並發的場景下會出現accept queue滿的情況。

十、調整backlog到底有多大效果?

針對這個問題,我們還專門做了個試驗了下,從實驗結果看調整帶來的效果還是比較明顯的。

服務端:1台8C的物理機器

客戶端:10台4C的docker

Backlog 每秒並發建連數 SYN包s被丟?
128 3000
128 5000 少量丟包
1024 5000
1024 10000

可以看到,對8C的機器backlog為128的情況下,在每秒5000建連的時候就會出現syn丟包。在調整到1024之後,即使10000也沒有任何問題。當然,這裡提醒下,不要盲目的調整到很高的值,是否可以調整到這麼高,還要結合各自服務器的配置以及業務場景。

作者介紹

顧海洋,攜程框架架構研發部技術專家,負責攜程分佈式服務化領域的工作。目前主要負責 Dubbo 在攜程的二次開發和推廣工作。

李偉,攜程雲平台技術專家,2012年加入攜程,目前專注於雲原生方向技術的研究和落地,先後參與負責過攜程部署架構改造、接入層架構升級等項目的設計和推廣。

本文轉載自公眾號攜程技術(ID:ctriptech)。

原文鏈接

https://mp.weixin.qq.com/s?__biz=MjM5MDI3MjA5MQ==&mid=2697269281&idx=1&sn=14967f9304feef0aa3213e68718760b1&chksm=8376ef15b4016603dec6f82515462b1185ec4f88e5c28fa082036e7404e1a399f76c4f56976a&scene=27#wechat_redirect