解Bug之路-dubbo流量上線時的非平滑問題

時間  2020-08-18
標籤 bug 之路 dubbo 流量 上線 平滑 問題 欄目 Dubbo 简体版
原文   原文鏈接

前言

筆者最近解決了一個困擾了業務系統好久的問題。這個問題只在發佈時出現，每次隻影響一兩次調用，相較於其它的問題來講，這個問題有點不夠受重視。因爲種種緣由，使得這個問題到了業務必須解決的程度，因而就到了筆者的手上。redis

問題現場

咱們採用的是dubbo服務，這是個穩定成熟的RPC框架。可是咱們在某些應用中會發現，只要這個應用一發布(或者重啓),就會出現請求超時的問題，以下圖所示:

並且都是第一筆請求會報錯，以後就再也沒有問題了。bootstrap

排查日誌

好了，現象咱們知道了，因而開始排查那個時間點的日誌。Server端沒有任何日誌，而Client(App1)端報錯超時。報錯以下所示:cookie

2019-08-22 20:33:50.798
com.alibaba.dubbo.rpc.RpcException:
	Failed to invoke the method set in the servce XXXFacade,
	tries 1 times
	......
	start time: 2019-08-22 20:32:50.474
	end time: 2019-08-22 30:33:50.767 
	timeout=60000,channel:/1.1.1.1:44502->2.2.2.2:20880

看日誌報錯是這個tcp五元組(1.1.1.1:44502->2.2.2.2:20880)有問題。因而筆者netstat了一下，查看當前此鏈接的狀態:併發

netstat -anp | grep 44502
1.1.1.1:44502 2.2.2.2:20880 ESTABLISHED

這個鏈接處於正常的ESTABLISHED狀態，並且調用2.2.2.2這個server的鏈接只有這一個,那後續這臺機器調用2.2.2.2這個server確定只用到了這個鏈接，查看日誌發現除了這一筆，其它調用一切正常。框架

思路1:Server端處理超時

按照上面的報錯，確定這個鏈接有問題，按照正常思路，是不是第一筆調用的時候各類初始化過程(以及jit)致使server處理請求過慢?以下圖所示:

但這個問題很快被第二筆請求(和第一筆請求間隔只有一秒)給否決了。也就是說第一筆請求花了60s還超時，而第二筆請求在第一筆請求發出後的一秒後發出就成功了(並且耗時是毫秒級的)。若是按照上述思路，第二筆請求也應該等各類初始化完成以後再處理，也應該卡至關長的一段時間纔對。再加上server端沒有任何日誌，就感受好像沒有收到請求。異步

思路2:Client端沒有發送成功

因而咱們開始了思路2，Client端沒有發送成功。因爲Dubbo是基於Netty的，其請求傳輸的處理過程是個NIO的異步化過程(只不過經過使用future機制對業務來講是同步的)。首先咱們看下dubbo的超時檢測機制,以下圖所示:

固然，還有future的超時機制,這邊我就不列舉出來了。從這個機制能夠看出，就算Client端發送的時候(由於寫是寫到socket的writebuffer裏面，通常不會滿，因此不會報錯)沒有發送出去,也不會在發的那一刻報出錯誤，而是要等定時掃描。爲了驗證這個猜測，筆者就開始着手排查鏈接的日誌。jvm

鏈接日誌

由於規律是第一筆失敗，那麼筆者開始懷疑鏈接建立的有問題,但後面的請求成功又代表鏈接建立是沒有問題的。那麼，是不是鏈接尚未建立好就發送了第一筆請求呢？帶着這樣的疑問，筆者找到了以下的日誌:socket

2019-08-22 20:32:51.876 （DubboClientReconnectTimer-thread-1) Successed connect to server /1.1.1.1:20880 ... channel is 
NettyChannel /1.1.1.1:44502 => /2.2.2.2:20880

由日誌所示,1.1.1.1:44502這個鏈接串是在2019-08-22 20:32:51.876鏈接成功的，而上面出錯的日誌起始時間爲tcp

請求發送時間:2019-08-22 20:32:50.474
鏈接開始創建時間:2019-08-22 20:32:51.876
鏈接成功創建時間:2019-08-22 20:32:51.876

請求在鏈接成功創建以前，感受很是符合筆者上述的猜測。但細想又不對，上述日誌表示的是在2019-08-22 20:32:51.876開始創建鏈接並在1ms內創建成功鏈接。而請求確是50s發出的，dubbo自己代碼不可能在鏈接還沒作出建立動做的時候就開始發送請求(由於44502是由kernel分配的，沒到建立鏈接動做以前是不可能知道這個端口號的,但它卻在日誌裏面打印出來了),以下圖所示：

思考了一段時間，筆者以爲這種狀況頗有多是日誌是不許確的，它僅僅打印當前鏈接包裝類中的信息，以前那個出錯的鏈接已經被新建的鏈接掩蓋了(在日誌中)。咱們看下dubbo中對應的打印日誌代碼:ide

private String getTimeoutMessage(boolean scan) {
        long nowTimestamp = System.currentTimeMillis();
        return (sent > 0 ? "Waiting server-side response timeout" : "Sending request timeout in client-side")
                + (scan ? " by scan timer" : "") + ". start time: "
                + (new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS").format(new Date(start))) + ", end time: "
                + (new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS").format(new Date())) + ","
                + (sent > 0 ? " client elapsed: " + (sent - start)
                + " ms, server elapsed: " + (nowTimestamp - sent)
                : " elapsed: " + (nowTimestamp - start)) + " ms, timeout: "
                + timeout + " ms, request: " + request + ", channel: " + channel.getLocalAddress()
                + " -> " + channel.getRemoteAddress();
    }

這個1.1.1.1:44502是由channel.getLocalAddress()得出的,咱們看下調用鏈:

channel.getLocalAddress()
	|->nettyClient.channel.getLocalAddress()

筆者看了下代碼，dubbo在reconnect(從新鏈接的時候)會把nettyClient.channel換掉，從而可能打印出來和發送請求時不一樣的client端口信息。再加上日誌裏面打印出來的線程號DubboClientReconnectTimer-thread-1就幾乎能夠肯定，以前還有一個鏈接，只不過這個鏈接失敗了，新建的鏈接爲1.1.1.1f
:44502。再仔細的找了下日誌，發現了下面這條日誌:

------------------日誌分割線----------------
2019-08-22 20:32:51,876（DubboClientReconnectTimer-thread-1)  Close old Netty channel /1.1.1.1:44471 :> 2.2.2.2:20880
on create new netty channel /1.1.1.1:44502 => /2.2.2.2:20880
------------------日誌分割線----------------
2019-08-22 20:32:51.876 （DubboClientReconnectTimer-thread-1) Successed connect to server /1.1.1.1:20880 ... channel is 
NettyChannel /1.1.1.1:44502 => /2.2.2.2:20880

便是說dubbo在把1.1.1.1:44471關閉後，立馬建立了2.2.2.2:44502
那麼總體過程以下圖所示:

咱們看下1.1.1.1:44471是何時建立的,繼續搜尋日誌:

zgrep '1.1.1.1:44471' dubbo.log.1.zip
2019-08-22 20:31:59.871 (ZkClient-EventThread-23) Successed connect to server /2.2.2.2:20880 ... channel is 
NettyChannel /1.1.1.1: 44471 => /2.2.2.2:20880
------------------日誌分割線----------------
2019-08-22 20:32:51,876（DubboClientReconnectTimer-thread-1)  Close old Netty channel /1.1.1.1:44471 :> 2.2.2.2:20880

發現其在

鏈接1建立時間:2019-08-22 20:31:59.871
請求發送時間:2019-08-22 20:32:50.474
鏈接1關閉時間:2019-08-22 20:32:51,876

並且筆者翻看了業務日誌，發現鏈接1在其生命週期內有且只有一筆請求，這筆請求就是報錯的請求，由此能夠看出這個鏈接1從創建成功開始就沒法使用。

爲何鏈接創建成功確沒法使用

首先因爲dubbo是基於netty的，這種成熟的普遍應用的框架在建立鏈接這種問題上不該該會有問題。
而筆者仔細翻看netty翻看netty源碼也確實遵照了NIO的編寫套路。那麼問題可能出如今環境上,既然應用(client/server)自己日誌找不到更多的有用信息，那麼看看操做系統可否有什麼能夠追尋的蛛絲馬跡。因而筆者首先用dmesg查看下kernel打印的日誌，client端沒發現什麼有用的信息，但server端的dmesg引發了筆者的注意

possible SYN flooding on port 20880. Sending cookies.
possible SYN flooding on port 20880. Sending cookies.
possible SYN flooding on port 20880. Sending cookies.
possible SYN flooding on port 20880. Sending cookies.
possible SYN flooding on port 20880. Sending cookies.

其字面意思爲kenerl自己可能在20880端口遭到了SYN泛洪攻擊，發送cookies。
這種日誌會在併發鏈接過多的狀況下由kernel打印出來。筆者netstat了下頻繁出問題的機器，發現其特色都是鏈接特別多(達到了好幾千甚至上萬)。而dubbo的上線機制是隻要註冊到zookeeper後，zookeeper給全部的機器推送，全部的機器立馬鏈接，這樣就會形成比較高的併發鏈接，以下圖所示:

既然懷疑到了高併發connect，那麼筆者就立馬用netstat看下kernel對於tcp的統計信息:

netstat -s
...
TcpExt:
	...
	1607 times the listen queue of a socket overflowed
	...

果真有這種併發鏈接致使的統計信息,socket overflowed表示的是server端的tcp_backlog隊列溢出了。到這裏筆者有八成把握是這個tcp_backlog設置的太小的問題了。下面就是分析，tcp_backlog溢出爲何會致使上述鏈接雖然成功可是第一筆報錯的現象，從而和日誌相印證，來證實筆者的猜想。

tcp_backlog溢出分析

tcp的三次握手

先從tcp的三次握手進行着手分析，從tcp_v4_do_rcv函數進行入手，由於這個函數是tcp協議獲取packet的地方,當三次握手的SYN第一次進來的時候，應該會走這個函數:

// 先考察一下三次握手的第一個SYN
int tcp_v4_do_rcv(struct sock *sk, struct sk_buff *skb){
	if (sk->sk_state == TCP_LISTEN) {
		......
		// 因爲如今鏈接處於第一個SYN,如今server端的socket處於LISTEN狀態
		struct sock *nsk = tcp_v4_hnd_req(sk, skb);
		......
	}
}
// 咱們繼續看下tcp_v4_hnd_req代碼,三次握手第一個SYN kernel走的分支
tcp_v4_do_rcv
	/* 因爲tcp_v4_hnd_req沒有發現和此五元組對應的鏈接,因此do nothing */
	|->tcp_v4_hnd_req
	|->tcp_rcv_state_process
			/** case TCP_LISTEN && th->syn */
			|->conn_request(tcp_v4_conn_request)

咱們繼續分析conn_request函數，因爲裏面不少邏輯，因此咱們濾掉了不少細節:

int tcp_v4_conn_request(struct sock *sk, struct sk_buff *skb) {
	// 若是csk的reqsk queue滿了，則設置want_cookie標識
	if (inet_csk_reqsk_queue_is_full(sk) && !isn) {
		if (sysctl_tcp_syncookies) {
			want_cookie = 1;
		}
		......
		if(want_cookie){
			// 下面這行就是打印possible SYN flooding的地方
			syn_flood_warning(skb);
			......
		}
		// 發送synack,即三次握手的第二次握手
		// 注意want_cookie的時候並不把對應的req加入到reqsk的hash列表中
		if (__tcp_v4_send_synack(sk, req, dst) || want_cookie)
			goto drop_and_free;
		// 若是發送syack成功，則加到hash列表裏面
		inet_csk_reqsk_queue_hash_add(sk, req, TCP_TIMEOUT_INIT);
		......
		drop_and_free;
			reqsk_free(req);
		return 0;
	}
}

上面就是三次握手的前兩次握手，以下圖所示:

如今讓咱們看下最關鍵的第三次握手(客戶端發給server ack的過程),依舊從tcp_v4_do_rcv開始

tcp_v4_hnd_req
	|->tcp_v4_hnd_req
// 這裏面分兩種狀況
static struct sock *tcp_v4_hnd_req(struct sock *sk, struct sk_buff *skb){
	// 首先從inet_csk_search_req看是否有對應的五元組
	struct request_sock *req = inet_csk_search_req(sk, &prev, th->source,
						       iph->saddr, iph->daddr);
	// 這邊的req分支下的tcp_check_req是重點，咱們下面再分析
	if (req)
		return tcp_check_req(sk, skb, req, prev);
	// 處理established狀況
	// 若是inet_csk沒找到，則多是須要syn cookie，處理syn cookie
	// 下面這條語句應該是在syn
	sk = cookie_v4_check(sk, skb, &(IPCB(skb)->opt));
	// 若是處理成功，則把其加入到inet_csk_reqsk_queue_add隊列中
	......					     
}

上面這些代碼片斷主要代表的就是若是三次握手成功，會在server端把新建立的server端sock放到inet_csk_reqsk裏面，而後由後面的tcp_child_process去處理。

tcp_check_req

上面分析完大體的tcp三次握手代碼邏輯以後，咱們如今看看形成本文問題現象的核心分支tcp_check_req,這個是在對應的req被放到inet_csk_reqsk(即不須要cookie或者cookie校驗成功)後才能執行到這一句,源碼以下:

// 下邊是client ack回來後的處理過程
// 筆者爲了簡單起見，咱們省略cookie校驗的邏輯
struct sock *tcp_check_req(......){
	/* 各類處理，各類校驗 */
	child = inet_csk(sk)->icsk_af_ops->syn_recv_sock(sk, skb, req, 	NULL);
	// 若是syn_recv_sock返回空，則跳到listen_overflow
	if (child == NULL)
		goto listen_overflow;
	......
listen_overflow:
	// 若是沒有設置tcp_abort_on_overflow則設置acked=1
	if (!sysctl_tcp_abort_on_overflow) {
		inet_rsk(req)->acked = 1;
		return NULL;
	}}
	// 增長內核統計參數
	NET_INC_STATS_BH(sock_net(sk), LINUX_MIB_EMBRYONICRSTS);
	// 若是設置了tcp_abort_on_overflow則發送reset報文
	if (!(flg & TCP_FLAG_RST))
		req->rsk_ops->send_reset(sk, skb);
	// 同時將當前sock從csk_reqsk中刪除，即當client端下次報文過來的時候，沒法找到
	// 對應的csk_reqsk
	inet_csk_reqsk_queue_drop(sk, req, prev);
	return NULL;

若是進了listen_overflow分支,server端會有兩種現象，一個是直接將acked設置爲1(僅設置標識不發送ack),另外一個是發送ack。這兩個分支都會把對應的req從reqsk_queue中刪除。下圖就是走了listen_overflow後不一樣分之,三次握手的狀況:

不設置tcp_abort_on_overflow

設置tcp_abort_on_overflow

由上面看出設置了tcp_abort_on_overflow會在三次握手以後立馬置爲closed狀態，二不設置tcp_abort_on_overflow會等第一個請求發出來的時候纔會知道這個鏈接其實已經被server端丟棄了。

何時listen_overflow

看上面的代碼，即在syn_recv_sock返回null的時候，會到listen_overflow，對應的tcp協議的函數爲:

struct sock *tcp_v4_syn_recv_sock(struct sock *sk, struct sk_buff *skb,
				  struct request_sock *req,
				  struct dst_entry *dst){
		....
		if (sk_acceptq_is_full(sk))
			goto exit_overflow;
		......
}

sk_acceptq_is_full裏面判斷full的隊列長度是下面這三個參數中的最小值:

取三者中的最小值
/proc/sys/inet/ipv4/tcp_max_syn_backlog
/proc/sys/net/core/somaxconn
tcp listen函數調用時候傳入的back_log

限於篇幅，就不給出這裏判斷隊列是否爲full的源碼了。

修復方案

設置kernel參數

一開始筆者僅僅在server端設置了下面這三個參數(天真的覺得dubbo考慮到了backlog,設置了一個較大的數值，其實其用了jdk默認的50)

注意，這邊511是根據redis的建議值設置的
/proc/sys/inet/ipv4/tcp_max_syn_backlog 511
/proc/sys/net/core/somaxconn 511
/proc/sys/net/ipv4/tcp_abort_on_overflow 1

發現依舊有Close old netty client這樣的錯誤日誌,可是業務方確告訴筆者已經沒有上線流量損失的狀況了。筆者上去觀察了一下狀況，發現沒有流量損失是因爲如上圖所述reset報文立馬發回來，致使可以出錯的時間窗口縮小爲2s,而不是以前的第一筆必報錯，2s內因爲沒有任何請求，因此大大減小了出錯機率。以下圖所示:

而建立鏈接和close old netty client日誌的間隔都是小於等於兩秒也證實了tcp_abort_on_overflow生效了

dubbo代碼增長backlog的設置

因爲dubbo用的是jdk默認的backlog(50),因此筆者在dubbo源碼對應的部分作了調整，以下代碼所示:

public class NettyServer extends AbstractServer implements Server {
	......
	protected void doOpen() throws Throwable {
		...
		// 能夠從jvm參數中動態調整這個backlog
		String backlog = System.getProperty(BACK_LOG_KEY);
		if(StringUtils.isEmpty(backlog)){
			// 默認爲2048,這邊調大點，反正改內核參數是即時生效的
			backlog = DEFAULT_BACK_LOG;
		}
		bootstrap.setOption("backlog",backlog);
		......
	}
}

將這個修改過的dubbo版本給業務方(server端)用了之後，再也沒有對應的報錯日誌了，dubbo上線也平滑了。

總結

事實上，從開始分析問題到猜想要調整backlog所花費的時間並不長。可是筆者喜歡把全部的細節和本身的猜測一一印證，經過源碼分析出來的過程圖景可以將全部的問題現象所有解釋，是一件很爽快的事情。

公衆號

關注筆者公衆號，獲取更多幹貨文章:

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程