## 前言 筆者最近解決了一個困擾了業務系統很久的問題。這個問題只在釋出時出現，每次隻影響一兩次呼叫，相較於其它的問題來說，這個問題有點不夠受重視。由於種種原因，使得這個問題到了業務必須解決的程度，於是就到了筆者的手上。 ## 問題現場 我們採用的是dubbo服務，這是個穩定成熟的RPC框架。但是我們在某些應用中會發現，只要這個應用一發布(或者重啟),就會出現請求超時的問題，如下圖所示:  而且都是第一筆請求會報錯，之後就再也沒有問題了。 ## 排查日誌 好了，現象我們知道了，於是開始排查那個時間點的日誌。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了一下，檢視當前此連線的狀態: ``` 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裡面，一般不會滿，所以不會報錯)沒有傳送出去,也不會在發的那一刻報出錯誤，而是要等定時掃描。為了驗證這個猜想，筆者就開始著手排查連線的日誌。 ## 連線日誌 因為規律是第一筆失敗，那麼筆者開始懷疑連線建立的有問題,但後面的請求成功又表明連線建立是沒有問題的。那麼，是否是連線還沒有建立好就傳送了第一筆請求呢？帶著這樣的疑問，筆者找到了如下的日誌: ``` 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連線成功的，而上面出錯的日誌起始時間為 ``` 請求傳送時間: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(); } ``` 這個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所花費的時間並不長。但是筆者喜歡把所有的細節和自己的猜想一一印證，通過原始碼分析出來的過程圖景能夠將所有的問題現象全部解釋，是一件很爽快的事情。 ## 公眾號 關注筆者公眾號，獲取更多幹貨文章: