如何解決dubbo流量上線時的非平滑問題

如何解決dubbo流量上線時的非平滑問題，很多新手對此不是很清楚，為了幫助大家解決這個難題，下面小編將為大家詳細講解，有這方面需求的人可以來學習下，希望你能有所收獲。

前言

筆者最近解決了一個困擾了業(yè)務系統(tǒng)很久的問題。這個問題只在發(fā)布時出現(xiàn)，每次只影響一兩次調(diào)用，相較于其它的問題來說，這個問題有點不夠受重視。由于種種原因，使得這個問題到了業(yè)務必須解決的程度，于是就到了筆者的手上。

問題現(xiàn)場

我們采用的是dubbo服務，這是個穩(wěn)定成熟的RPC框架。但是我們在某些應用中會發(fā)現(xiàn)，只要這個應用一發(fā)布(或者重啟),就會出現(xiàn)請求超時的問題，如下圖所示:
而且都是第一筆請求會報錯，之后就再也沒有問題了。

排查日志

好了，現(xiàn)象我們知道了，于是開始排查那個時間點的日志。Server端沒有任何日志，而Client(App1)端報錯超時。報錯如下所示:

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了一下，查看當前此連接的狀態(tài):

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

這個連接處于正常的ESTABLISHED狀態(tài)，而且調(diào)用2.2.2.2這個server的連接只有這一個,那后續(xù)這臺機器調(diào)用2.2.2.2這個server肯定只用到了這個連接，查看日志發(fā)現(xiàn)除了這一筆，其它調(diào)用一切正常。

思路1:Server端處理超時

按照上面的報錯，肯定這個連接有問題，按照正常思路，是否是第一筆調(diào)用的時候各種初始化過程(以及jit)導致server處理請求過慢?如下圖所示:
但這個問題很快被第二筆請求(和第一筆請求間隔只有一秒)給否決了。也就是說第一筆請求花了60s還超時，而第二筆請求在第一筆請求發(fā)出后的一秒后發(fā)出就成功了(而且耗時是毫秒級的)。如果按照上述思路，第二筆請求也應該等各種初始化完成之后再處理，也應該卡相當長的一段時間才對。再加上server端沒有任何日志，就感覺好像沒有收到請求。

思路2:Client端沒有發(fā)送成功

于是我們開始了思路2，Client端沒有發(fā)送成功。由于Dubbo是基于Netty的，其請求傳輸?shù)奶幚磉^程是個NIO的異步化過程(只不過通過使用future機制對業(yè)務來說是同步的)。首先我們看下dubbo的超時檢測機制,如下圖所示:
當然，還有future的超時機制,這邊我就不列舉出來了。從這個機制可以看出，就算Client端發(fā)送的時候(因為寫是寫到socket的writebuffer里面，一般不會滿，所以不會報錯)沒有發(fā)送出去,也不會在發(fā)的那一刻報出錯誤，而是要等定時掃描。為了驗證這個猜想，筆者就開始著手排查連接的日志。

連接日志

因為規(guī)律是第一筆失敗，那么筆者開始懷疑連接創(chuàng)建的有問題,但后面的請求成功又表明連接創(chuàng)建是沒有問題的。那么，是否是連接還沒有創(chuàng)建好就發(fā)送了第一筆請求呢？帶著這樣的疑問，筆者找到了如下的日志:

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連接成功的，而上面出錯的日志起始時間為

請求發(fā)送時間: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內(nèi)建立成功連接。而請求確是50s發(fā)出的，dubbo本身代碼不可能在連接還沒做出創(chuàng)建動作的時候就開始發(fā)送請求(因為44502是由kernel分配的，沒到創(chuàng)建連接動作之前是不可能知道這個端口號的,但它卻在日志里面打印出來了),如下圖所示：
思考了一段時間，筆者覺得這種情況很有可能是日志是不準確的，它僅僅打印當前連接包裝類中的信息，之前那個出錯的連接已經(jīng)被新建的連接掩蓋了(在日志中)。我們看下dubbo中對應的打印日志代碼:

    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()得出的,我們看下調(diào)用鏈:

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

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

------------------日志分割線----------------
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關(guān)閉后，立馬創(chuàng)建了2.2.2.2:44502 那么整體過程如下圖所示:
我們看下1.1.1.1:44471是什么時候創(chuàng)建的,繼續(xù)搜尋日志:

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

發(fā)現(xiàn)其在

連接1創(chuàng)建時間:2019-08-22 20:31:59.871
請求發(fā)送時間:2019-08-22 20:32:50.474
連接1關(guān)閉時間:2019-08-22 20:32:51,876

而且筆者翻看了業(yè)務日志，發(fā)現(xiàn)連接1在其生命周期內(nèi)有且只有一筆請求，這筆請求就是報錯的請求，由此可以看出這個連接1從建立成功開始就無法使用。

為什么連接建立成功確無法使用

首先由于dubbo是基于netty的，這種成熟的廣泛應用的框架在創(chuàng)建連接這種問題上不應該會有問題。 而筆者仔細翻看netty翻看netty源碼也確實遵守了NIO的編寫套路。那么問題可能出現(xiàn)在環(huán)境上,既然應用(client/server)本身日志找不到更多的有用信息，那么看看操作系統(tǒng)能否有什么可以追尋的蛛絲馬跡。于是筆者首先用dmesg查看下kernel打印的日志，client端沒發(fā)現(xiàn)什么有用的信息，但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泛洪攻擊，發(fā)送cookies。 這種日志會在并發(fā)連接過多的情況下由kernel打印出來。筆者netstat了下頻繁出問題的機器，發(fā)現(xiàn)其特點都是連接特別多(達到了好幾千甚至上萬)。而dubbo的上線機制是只要注冊到zookeeper后，zookeeper給所有的機器推送，所有的機器立馬連接，這樣就會造成比較高的并發(fā)連接，如下圖所示:
既然懷疑到了高并發(fā)connect，那么筆者就立馬用netstat看下kernel對于tcp的統(tǒng)計信息:

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

果然有這種并發(fā)連接導致的統(tǒng)計信息,socket overflowed表示的是server端的tcp_backlog隊列溢出了。到這里筆者有八成把握是這個tcp_backlog設置的過小的問題了。下面就是分析，tcp_backlog溢出為什么會導致上述連接雖然成功但是第一筆報錯的現(xiàn)象，從而和日志相印證，來證明筆者的猜測。

tcp_backlog溢出分析

tcp的三次握手

先從tcp的三次握手進行著手分析，從tcp_v4_do_rcv函數(shù)進行入手，因為這個函數(shù)是tcp協(xié)議獲取packet的地方,當三次握手的SYN第一次進來的時候，應該會走這個函數(shù):

// 先考察一下三次握手的第一個SYN
int tcp_v4_do_rcv(struct sock *sk, struct sk_buff *skb){
	if (sk->sk_state == TCP_LISTEN) {
		......
		// 由于現(xiàn)在連接處于第一個SYN,現(xiàn)在server端的socket處于LISTEN狀態(tài)
		struct sock *nsk = tcp_v4_hnd_req(sk, skb);
		......
	}
}
// 我們繼續(xù)看下tcp_v4_hnd_req代碼,三次握手第一個SYN kernel走的分支
tcp_v4_do_rcv
	/* 由于tcp_v4_hnd_req沒有發(fā)現(xiàn)和此五元組對應的連接,所以do nothing */
	|->tcp_v4_hnd_req
	|->tcp_rcv_state_process
			/** case TCP_LISTEN && th->syn */
			|->conn_request(tcp_v4_conn_request)

我們繼續(xù)分析conn_request函數(shù)，由于里面很多邏輯，所以我們?yōu)V掉了很多細節(jié):

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);
			......
		}
		// 發(fā)送synack,即三次握手的第二次握手
		// 注意want_cookie的時候并不把對應的req加入到reqsk的hash列表中
		if (__tcp_v4_send_synack(sk, req, dst) || want_cookie)
			goto drop_and_free;
		// 如果發(fā)送syack成功，則加到hash列表里面
		inet_csk_reqsk_queue_hash_add(sk, req, TCP_TIMEOUT_INIT);
		......
		drop_and_free;
			reqsk_free(req);
		return 0;
	}
}

上面就是三次握手的前兩次握手，如下圖所示:
現(xiàn)在讓我們看下最關(guān)鍵的第三次握手(客戶端發(fā)給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端把新創(chuàng)建的server端sock放到inet_csk_reqsk里面，然后由后面的tcp_child_process去處理。

tcp_check_req

上面分析完大致的tcp三次握手代碼邏輯之后，我們現(xiàn)在看看造成本文問題現(xiàn)象的核心分支tcp_check_req,這個是在對應的req被放到inet_csk_reqsk(即不需要cookie或者cookie校驗成功)后才能執(zhí)行到這一句,源碼如下:

// 下邊是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;
	}}
	// 增加內(nèi)核統(tǒng)計參數(shù)
	NET_INC_STATS_BH(sock_net(sk), LINUX_MIB_EMBRYONICRSTS);
	// 如果設置了tcp_abort_on_overflow則發(fā)送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端會有兩種現(xiàn)象，一個是直接將acked設置為1(僅設置標識不發(fā)送ack),另一個是發(fā)送ack。這兩個分支都會把對應的req從reqsk_queue中刪除。下圖就是走了listen_overflow后不同分之,三次握手的情況:

不設置tcp_abort_on_overflow

設置tcp_abort_on_overflow
由上面看出設置了tcp_abort_on_overflow會在三次握手之后立馬置為closed狀態(tài)，二不設置tcp_abort_on_overflow會等第一個請求發(fā)出來的時候才會知道這個連接其實已經(jīng)被server端丟棄了。

什么時候listen_overflow

看上面的代碼，即在syn_recv_sock返回null的時候，會到listen_overflow，對應的tcp協(xié)議的函數(shù)為:

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的隊列長度是下面這三個參數(shù)中的最小值:

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

限于篇幅，就不給出這里判斷隊列是否為full的源碼了。

修復方案

設置kernel參數(shù)

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

注意，這邊511是根據(jù)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

發(fā)現(xiàn)依舊有Close old netty client這樣的錯誤日志,但是業(yè)務方確告訴筆者已經(jīng)沒有上線流量損失的情況了。筆者上去觀察了一下情況，發(fā)現(xiàn)沒有流量損失是由于如上圖所述reset報文立馬發(fā)回來，導致能夠出錯的時間窗口縮小為2s,而不是之前的第一筆必報錯，2s內(nèi)由于沒有任何請求，所以大大減少了出錯概率。如下圖所示:
而創(chuàng)建連接和close old netty client日志的間隔都是小于等于兩秒也證明了tcp_abort_on_overflow生效了

dubbo代碼增加backlog的設置

由于dubbo用的是jdk默認的backlog(50),所以筆者在dubbo源碼對應的部分做了調(diào)整，如下代碼所示:

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

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

事實上，從開始分析問題到猜測要調(diào)整backlog所花費的時間并不長。但是筆者喜歡把所有的細節(jié)和自己的猜想一一印證，通過

看完上述內(nèi)容是否對您有幫助呢？如果還想對相關(guān)知識有進一步的了解或閱讀更多相關(guān)文章，請關(guān)注億速云行業(yè)資訊頻道，感謝您對億速云的支持。