前言
筆者最近解決了一個困擾了業務系統很久的問題。這個問題只在發佈時出現，每次隻影響一兩次調用，相較於其它的問題來說，這個問題有點不夠受重視。由於種種原因，使得這個問題到了業務必須解決的程度，於是就到了筆者的手上。
問題現場
我們採用的是dubbo服務，這是個穩定成熟的RPC框架。但是我們在某些應用中會發現，只要這個應用一發布(或者重啟),就會出現請求超時的問題，如下圖所示:
而且都是第一筆請求會報錯，之後就再也沒有問題了。
排查日誌
好了，現象我們知道了，於是開始排查那個時間點的日誌。Server端沒有任何日誌，而Client(App1)端報錯超時。報錯如下所示:
2019-08-22 20:33:50.798
com.alibaba.dubbo.rpc.RpcException:
\tFailed to invoke the method set in the servce XXXFacade,
\ttries 1 times
\t......
\tstart time: 2019-08-22 20:32:50.474
\tend time: 2019-08-22 30:33:50.767
\ttimeout=60000,channel:/21.64.21.164:44502->21.64.35.75:20880
看日誌報錯是這個tcp五元組(21.64.21.164:44502->21.64.35.75:20880)有問題。於是筆者netstat了一下，查看當前此連接的狀態:
netstat -anp | grep 44502
21.64.21.164:44502 21.64.35.75:20880 ESTABLISHED
這個連接處於正常的ESTABLISHED狀態，而且調用21.64.35.75這個server的連接只有這一個,那後續這臺機器調用21.64.35.75這個server肯定只用到了這個連接，查看日誌發現除了這一筆，其它調用一切正常。
思路1:Server端處理超時
按照上面的報錯，肯定這個連接有問題，按照正常思路，是否是第一筆調用的時候各種初始化過程(以及jit)導致server處理請求過慢?如下圖所示:
但這個問題很快被第二筆請求(和第一筆請求間隔只有一秒)給否決了。也就是說第一筆請求花了60s還超時，而第二筆請求在第一筆請求發出後的一秒後發出就成功了(而且耗時是毫秒級的)。如果按照上述思路，第二筆請求也應該等各種初始化完成之後再處理，也應該卡相當長的一段時間才對。再加上server端沒有任何日誌，就感覺好像沒有收到請求。
思路2:Client端沒有發送成功
於是我們開始了思路2，Client端沒有發送成功。由於Dubbo是基於Netty的，其請求傳輸的處理過程是個NIO的異步化過程(只不過通過使用future機制對業務來說是同步的)。首先我們看下dubbo的超時檢測機制,如下圖所示:
當然，還有future的超時機制,這邊我就不列舉出來了。從這個機制可以看出，就算Client端發送的時候(因為寫是寫到socket的writebuffer裡面，一般不會滿，所以不會報錯)沒有發送出去,也不會在發的那一刻報出錯誤，而是要等定時掃描。為了驗證這個猜想，筆者就開始著手排查連接的日誌。
連接日誌
因為規律是第一筆失敗，那麼筆者開始懷疑連接創建的有問題,但後面的請求成功又表明連接創建是沒有問題的。那麼，是否是連接還沒有創建好就發送了第一筆請求呢？帶著這樣的疑問，筆者找到了如下的日誌:
2019-08-22 20:32:51.876 （DubboClientReconnectTimer-thread-1) Successed connect to server /21.64.35.75:20880 ... channel is
NettyChannel /21.64.21.164:44502 => /21.64.35.75:20880
由日誌所示,21.64.21.164:44502這個連接串是在2019-08-22 20:32:51.876連接成功的，而上面出錯的日誌起始時間為
請求發送時間: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中對應的打印日誌代碼:
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();
}
這個21.64.21.164:44502是由channel.getLocalAddress()得出的,我們看下調用鏈:
channel.getLocalAddress()
\t|->nettyClient.channel.getLocalAddress()
筆者看了下代碼，dubbo在reconnect(重新連接的時候)會把nettyClient.channel換掉，從而可能打印出來和發送請求時不同的client端口信息。再加上日誌裡面打印出來的線程號DubboClientReconnectTimer-thread-1就幾乎可以確定，之前還有一個連接，只不過這個連接失敗了，新建的連接為21.64.21.164:44502。再仔細的找了下日誌，發現了下面這條日誌:
------------------日誌分割線----------------
2019-08-22 20:32:51,876（DubboClientReconnectTimer-thread-1) Close old Netty channel /21.64.21.164:44471 :> 21.64.35.75:20880
on create new netty channel /21.64.21.164:44502 => /21.64.35.75:20880
------------------日誌分割線----------------
2019-08-22 20:32:51.876 （DubboClientReconnectTimer-thread-1) Successed connect to server /21.64.35.75:20880 ... channel is
NettyChannel /21.64.21.164:44502 => /21.64.35.75:20880
即是說dubbo在把21.64.21.164:44471關閉後，立馬創建了21.64.21.164:44502 那麼整體過程如下圖所示:
我們看下21.64.21.164:44471是什麼時候創建的,繼續搜尋日誌:
zgrep '21.64.21.164:44471' dubbo.log.1.zip
2019-08-22 20:31:59.871 (ZkClient-EventThread-23) Successed connect to server /21.64.35.75:20880 ... channel is
NettyChannel /21.64.21.164: 44471 => /21.64.35.75:20880
------------------日誌分割線----------------
2019-08-22 20:32:51,876（DubboClientReconnectTimer-thread-1) Close old Netty channel /21.64.21.164:44471 :> 21.64.35.75: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:
\t...
\t1607 times the listen queue of a socket overflowed
\t...
果然有這種併發連接導致的統計信息,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){
\tif (sk->sk_state == TCP_LISTEN) {
\t\t......
\t\t// 由於現在連接處於第一個SYN,現在server端的socket處於LISTEN狀態
\t\tstruct sock *nsk = tcp_v4_hnd_req(sk, skb);
\t\t......
\t}
}
// 我們繼續看下tcp_v4_hnd_req代碼,三次握手第一個SYN kernel走的分支
tcp_v4_do_rcv
\t/* 由於tcp_v4_hnd_req沒有發現和此五元組對應的連接,所以do nothing */
\t|->tcp_v4_hnd_req
\t|->tcp_rcv_state_process
\t\t\t/** case TCP_LISTEN && th->syn */
\t\t\t|->conn_request(tcp_v4_conn_request)
我們繼續分析conn_request函數，由於裡面很多邏輯，所以我們濾掉了很多細節:
int tcp_v4_conn_request(struct sock *sk, struct sk_buff *skb) {
\t// 如果csk的reqsk queue滿了，則設置want_cookie標識
\tif (inet_csk_reqsk_queue_is_full(sk) && !isn) {
\t\tif (sysctl_tcp_syncookies) {
\t\t\twant_cookie = 1;
\t\t}
\t\t......
\t\tif(want_cookie){
\t\t\t// 下面這行就是打印possible SYN flooding的地方
\t\t\tsyn_flood_warning(skb);
\t\t\t......
\t\t}
\t\t// 發送synack,即三次握手的第二次握手
\t\t// 注意want_cookie的時候並不把對應的req加入到reqsk的hash列表中
\t\tif (__tcp_v4_send_synack(sk, req, dst) || want_cookie)
\t\t\tgoto drop_and_free;
\t\t// 如果發送syack成功，則加到hash列表裡面
\t\tinet_csk_reqsk_queue_hash_add(sk, req, TCP_TIMEOUT_INIT);
\t\t......
\t\tdrop_and_free;
\t\t\treqsk_free(req);
\t\treturn 0;
\t}
}
上面就是三次握手的前兩次握手，如下圖所示:
現在讓我們看下最關鍵的第三次握手(客戶端發給server ack的過程),依舊從tcp_v4_do_rcv開始
tcp_v4_hnd_req
\t|->tcp_v4_hnd_req
// 這裡面分兩種情況
static struct sock *tcp_v4_hnd_req(struct sock *sk, struct sk_buff *skb){
\t// 首先從inet_csk_search_req看是否有對應的五元組
\tstruct request_sock *req = inet_csk_search_req(sk, &prev, th->source,
\t\t\t\t\t\t iph->saddr, iph->daddr);
\t// 這邊的req分支下的tcp_check_req是重點，我們下面再分析
\tif (req)
\t\treturn tcp_check_req(sk, skb, req, prev);
\t// 處理established情況
\t// 如果inet_csk沒找到，則可能是需要syn cookie，處理syn cookie
\t// 下面這條語句應該是在syn
\tsk = cookie_v4_check(sk, skb, &(IPCB(skb)->opt));
\t// 如果處理成功，則把其加入到inet_csk_reqsk_queue_add隊列中
\t......\t\t\t\t\t
}
上面這些代碼片段主要表明的就是如果三次握手成功，會在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(......){
\t/* 各種處理，各種校驗 */
\tchild = inet_csk(sk)->icsk_af_ops->syn_recv_sock(sk, skb, req, \tNULL);
\t// 如果syn_recv_sock返回空，則跳到listen_overflow
\tif (child == NULL)
\t\tgoto listen_overflow;
\t......
listen_overflow:
\t// 如果沒有設置tcp_abort_on_overflow則設置acked=1
\tif (!sysctl_tcp_abort_on_overflow) {
\t\tinet_rsk(req)->acked = 1;
\t\treturn NULL;
\t}}
\t// 增加內核統計參數
\tNET_INC_STATS_BH(sock_net(sk), LINUX_MIB_EMBRYONICRSTS);
\t// 如果設置了tcp_abort_on_overflow則發送reset報文
\tif (!(flg & TCP_FLAG_RST))
\t\treq->rsk_ops->send_reset(sk, skb);
\t// 同時將當前sock從csk_reqsk中刪除，即當client端下次報文過來的時候，無法找到
\t// 對應的csk_reqsk
\tinet_csk_reqsk_queue_drop(sk, req, prev);
\treturn 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,
\t\t\t\t struct request_sock *req,
\t\t\t\t struct dst_entry *dst){
\t\t....
\t\tif (sk_acceptq_is_full(sk))
\t\t\tgoto exit_overflow;
\t\t......
}
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 {
\t......
\tprotected void doOpen() throws Throwable {
\t\t...
\t\t// 可以從jvm參數中動態調整這個backlog
\t\tString backlog = System.getProperty(BACK_LOG_KEY);
\t\tif(StringUtils.isEmpty(backlog)){
\t\t\t// 默認為2048,這邊調大點，反正改內核參數是即時生效的
\t\t\tbacklog = DEFAULT_BACK_LOG;
\t\t}
\t\tbootstrap.setOption("backlog",backlog);
\t\t......
\t}
}
將這個修改過的dubbo版本給業務方(server端)用了以後，再也沒有對應的報錯日誌了，dubbo上線也平滑了。
總結
事實上，從開始分析問題到猜測要調整backlog所花費的時間並不長。但是筆者喜歡把所有的細節和自己的猜想一一印證，通過源碼分析出來的過程圖景能夠將所有的問題現象全部解釋，是一件很爽快的事情。
原文鏈接
https://my.oschina.net/alchemystar/blog/3098219
閱讀更多 rabbit兔兔 的文章
