分享一次排查CLOSE_WAIT過多的經驗

踩刀詩人發表於2021-04-05

關鍵詞:TCP、CLOSE_WAIT

 

問題背景

某日下午有測試人員急匆匆的跑來跟我反饋:“有客戶反饋供應商附件預覽不了,流程阻塞,需要緊急處理”,我立馬精神起來,畢竟都是付費客戶目前做B端業務,客戶都是付費使用者,不像C端,出了問題發個道歉宣告也就過去了)

 

等她說完,我第一時間用測試賬號登上去驗證,瀏覽器一直在轉圈,差不多一分鐘以後出了nginx的504錯誤頁。

 

 

 

初步排查

也許有人對504這個錯誤碼不熟悉,這裡借用百度百科的內容簡單介紹下這個錯誤碼。

 

504 Gateway Timeout

作為閘道器或者代理工作的伺服器嘗試執行請求時,未能及時從上游伺服器(URI標識出的伺服器,例如HTTP、FTP、LDAP)或者輔助伺服器(例如DNS)收到響應。

                                                                                                             (內容來源於百度百科)

 

看到這個錯誤碼第一反應就是下游服務太慢,導致nginx請求超時了,這裡的下游服務是自研的附件預覽服務,採用SpringBoot開發,整體的請求鏈路如下圖所示:

 

 

線上預覽的處理流程如下:

1.使用者在業務方站點發起預覽請求;

2.業務方拼接相關引數重定向到預覽服務;

3.預覽服務通過業務方傳遞的附件連結呼叫業務方介面下載附件到本地;

4.預覽服務將下載的附件轉換成html供使用者線上預覽;

 

結合上面的處理流程和請求鏈路,初步得到以下兩點猜測:

1.預覽服務呼叫業務方下載介面過慢;

2.預覽服務本身處理過慢;

 

帶著這兩點猜測我立馬去檢視日誌,結果卻大跌眼鏡,從昨天14點以後就沒有日誌輸出了。

請求進不來了?假死?掛了?

我首先確認程式是否存在,程式跑的好好的,為什麼會沒有請求呢,我第一反應是業務程式碼有問題,導致執行緒被hang佔滿了tomcat的執行緒池,所以立即使用jstack檢視執行緒情況,意外的是一切正常,執行緒數不多,更沒有發現死鎖、socket read0等可能導致執行緒hang住的情況。

 

自身沒問題,難道是被其他任務影響了,我繼續使用top檢視系統負載、cpu佔用等情況

 

 顯而易見,負載、cpu佔用都不高,似乎陷入了僵局。

 

 我猜測可能不是業務程式碼的問題,需要跳出業務程式碼去查問題,既然沒有請求,那就先從網路開始查起。

 

漸入佳境

先確認下服務端監聽埠是不是正常。

第一步:netstat 檢視網路狀態

netstat -aonp
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name     Timer
tcp       81      0 0.0.0.0:8080            0.0.0.0:*               LISTEN      1/java               off (0.00/0/0)
tcp        0      0 127.0.0.1:8100          0.0.0.0:*               LISTEN      24/soffice.bin       off (0.00/0/0)
tcp      936      0 172.20.4.203:8080       172.20.5.59:40576       CLOSE_WAIT  -                    off (0.00/0/0)
tcp      867      0 172.20.4.203:8080       172.20.4.172:57166      CLOSE_WAIT  -                    off (0.00/0/0)
tcp      964      0 172.20.4.203:8080       172.20.5.59:50106       CLOSE_WAIT  -                    off (0.00/0/0)
tcp     1701      0 172.20.4.203:8080       172.20.4.172:45428      CLOSE_WAIT  -                    off (0.00/0/0)
tcp     1169      0 172.20.4.203:8080       172.20.4.172:61582      CLOSE_WAIT  -                    off (0.00/0/0)
tcp      963      0 172.20.4.203:8080       172.20.4.172:64474      CLOSE_WAIT  -                    off (0.00/0/0)
tcp     1058      0 172.20.4.203:8080       172.20.5.59:44564       CLOSE_WAIT  -                    off (0.00/0/0)
tcp      962      0 172.20.4.203:8080       172.20.4.172:64160      CLOSE_WAIT  -                    off (0.00/0/0)
tcp     1733      0 172.20.4.203:8080       172.20.4.172:46810      CLOSE_WAIT  -                    off (0.00/0/0)
tcp     1587      0 172.20.4.203:8080       172.20.5.59:40032       CLOSE_WAIT  -                    off (0.00/0/0)
tcp      994      0 172.20.4.203:8080       172.20.4.172:47474      CLOSE_WAIT  -                    off (0.00/0/0)
tcp      867      0 172.20.4.203:8080       172.20.5.59:47134       CLOSE_WAIT  -                    off (0.00/0/0)
netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'
CLOSE_WAIT 103
ESTABLISHED 2

  

從輸出結果中可以確認預覽服務的監聽埠(8080)雖然是存活的,但有大量的CLOSE_WAIT出現,這顯然是不正常的,難道是CLOSE_WAIT過多導致超過了檔案描述符的限制,但是我在日誌中沒有找到“Too manay open files”,這個猜想隨之破滅,有沒有可能是tcp佇列溢位了?

 linux中一切皆檔案,ServerSocket每次accept一個socket意味著需要開啟一個檔案描述符,這個數量並不是無限的,系統中有限制,如果超過限制了就會報Too manay open files。

第二步:檢視tcp佇列是否溢位

netstat -s | egrep "listen|LISTEN" 
    243 times the listen queue of a socket overflowed
    243 SYNs to LISTEN sockets dropped

  

上面看到的 243 times ,表示全連線佇列溢位的次數,隔一陣重新整理一下,發現這個數字還在漲。

既然tcp佇列有溢位,自然是有部分請求到不了預覽服務了,在tcp層就被扔了,但是從昨天14點到現在一點日誌也沒有,難道都被扔了,繼續確認當前tcp佇列的情況。

關於tcp佇列的知識,這裡推薦去閱讀淘寶技術團隊寫的一篇文章,通俗易懂。http://jm.taobao.org/2017/05/25/525-1/

 

第三步:檢視tcp佇列當前情況

ss -lnt
State       Recv-Q Send-Q                                                                                           Local Address:Port                                                                                                          Peer Address:Port              
LISTEN      101    100   

  

Recv-Q代表當前全連線佇列的大小,也就是三次握手完成,目前在全連線佇列中等待被應用程式accept的socket個數。

Send-Q代表全連線佇列的最大值,應用程式可以在建立ServerSocket的時候指定,tomcat預設為100,但是這個值不能超過系統的/proc/sys/net/core/somaxconn,看看jdk中關於這個值的解釋,專業名詞叫backlog。

The maximum queue length for incoming connection indications (a
   request to connect) is set to the {@code backlog} parameter. If
   a connection indication arrives when the queue is full, the
     connection is refused.
 
 public ServerSocket(int port, int backlog) throws IOException {
        this(port, backlog, null);
 }    

  

從上面的輸出可以發現Recv-Q已經大於Send-Q,而且這個數量長時間不變,可以得出兩個結論:

1.部分socket一直堆積在佇列中沒有被accept;

2.由於tcp全連線佇列已滿,所以新的socket自然是進不來了。

至此可以初步解釋為什麼從昨天14點開始就一直沒有請求進來了。

 

深入分析

截止現在可以確定是由於tcp佇列滿導致一直沒有請求進來,但tcp佇列怎麼能從昨天14點一直滿到現在呢,jstack檢視當前執行緒並沒有什麼異常、top檢視系統負載、cpu都不高,是什麼讓tomcat不去tcp佇列中accept新的socket呢?

 

另一方面,通過tcp佇列滿這個現象也可以分析出為什麼那麼多的CLOSE_WAIT,因為socket在tcp的佇列中一直堆積著,還沒等到應用程式處理呢,就達到了nginx的超時時間,nginx主動關閉了連線,這裡貼一張經典的四次握手的圖。

 

 左邊的Initiator(發起者)就是nginx,右邊的Receiver(接受者)就是tomcat,nginx和tomcat通過三次握手已經建立了tcp連線,此時連線暫存在全連線佇列中,等待著tomcat去accept,但是tomcat遲遲不accept,一分鐘過後,nginx等不住了,主動發起了FIN開始關閉連線,此時tomcat側的tcp連線就處在CLOSE_WAIT狀態,理論上來講,tomcat收到nginx的FIN接著就應該close socket,CLOSE_WAIT狀態不會持續太久,難道是tomcat出bug了,沒有響應?

 

截止現在有兩個疑問:

1.為什麼tomcat不去tcp佇列中accept新的socket呢?

2.為什麼tomcat不響應nginx的關閉socket請求呢?

 

我們先看第一個疑問“為什麼tomcat不去tcp佇列中accept新的socket呢?”

要揭開這個疑問我們先看一張圖來感受下TCP握手過程中建連線的流程和佇列

 

 (圖片來源於https://tech.ebayinc.com/engineering/a-vip-connection-timeout-issue-caused-by-snat-and-tcp-tw-recycle/)

 

接下來的任務就是搞清楚tomcat是如何處理上圖中的accept邏輯的,我之前看過一部分tomcat原始碼,所以這裡直接拋個答案出來吧,就不延伸了,tomcat是通過一個單獨的Acceptor執行緒去accept socket的,accept之後扔給IO多路複用模組進行後續的業務處理,在這裡只需要關注處理accept那段邏輯就好,貼一下原始碼:

protected class Acceptor extends AbstractEndpoint.Acceptor {

        @Override
        public void run() {

            int errorDelay = 0;

            // Loop until we receive a shutdown command
            while (running) {

                // Loop if endpoint is paused
                while (paused && running) {
                    state = AcceptorState.PAUSED;
                    try {
                        Thread.sleep(50);
                    } catch (InterruptedException e) {
                        // Ignore
                    }
                }

                if (!running) {
                    break;
                }
                state = AcceptorState.RUNNING;

                try {
                    //if we have reached max connections, wait
                    countUpOrAwaitConnection();

                    SocketChannel socket = null;
                    try {
                        // Accept the next incoming connection from the server
                        // socket
                        socket = serverSock.accept();
                    } catch (IOException ioe) {
                        // We didn't get a socket
                        countDownConnection();
                        if (running) {
                            // Introduce delay if necessary
                            errorDelay = handleExceptionWithDelay(errorDelay);
                            // re-throw
                            throw ioe;
                        } else {
                            break;
                        }
                    }
                    // Successful accept, reset the error delay
                    errorDelay = 0;
                    // Configure the socket
                    if (running && !paused) {
                        // setSocketOptions() will hand the socket off to
                        // an appropriate processor if successful
                        if (!setSocketOptions(socket)) {
                            closeSocket(socket);
                        }
                    } else {
                        closeSocket(socket);
                    }
                } catch (Throwable t) {
                    ExceptionUtils.handleThrowable(t);
                    log.error(sm.getString("endpoint.accept.fail"), t);
                }
            }
            state = AcceptorState.ENDED;
        }

  

邏輯比較簡單,就是一直從ServerSocket中accept socket然後扔給IO多路複用模組,重點關注下60行,ExceptionUtils.handleThrowable(t)。

如果accept過程中拋了一個異常會怎樣?接著看下ExceptionUtils.handleThrowable(t)的處理邏輯:

/**
     * Checks whether the supplied Throwable is one that needs to be
     * rethrown and swallows all others.
     * @param t the Throwable to check
     */
    public static void handleThrowable(Throwable t) {
        if (t instanceof ThreadDeath) {
            throw (ThreadDeath) t;
        }
        if (t instanceof StackOverflowError) {
            // Swallow silently - it should be recoverable
            return;
        }
        if (t instanceof VirtualMachineError) {
            throw (VirtualMachineError) t;
        }
        // All other instances of Throwable will be silently swallowed
    }

  

如果是ThreadDeath和VirtualMachineError這兩類異常就繼續往上拋了,丟擲去意味著什麼呢?

 思考三秒鐘

 

 

 如果繼續往上拋說明Acceptor執行緒意外退出執行,自然就不會去tcp佇列中accept連線,佇列不堆積才怪呢,想到這兒我立馬去翻一下預覽服務的日誌,看會不會有什麼發現,其中有一條日誌引起了我的關注。

Exception in thread "http-nio-8080-Acceptor" java.lang.OutOfMemoryError: Java heap space

  

"http-nio-8080-Acceptor" 正是Acceptor執行緒的名字,說明Acceptor拋了一個OutOfMemoryError。

OutOfMemoryError和Acceptor退出有什麼關係呢,想想前面提到的handleThrowable邏輯“如果是ThreadDeath和VirtualMachineError這兩類異常就繼續丟擲”,這裡的OutOfMemoryError正是VirtualMachineError的一個子類。

public class OutOfMemoryError extends VirtualMachineError 

到這裡可以說真相大白,是因為記憶體不足導致Acceptor執行緒在accept的時候拋了OutOfMemoryError,執行緒直接退出,所以導致大量連線堆積在tcp佇列中。

 

其實到這兒第二個疑問“為什麼tomcat不響應nginx的關閉socket請求呢?”也就很好解釋了,因為Acceptor的退出,堆積在tcp佇列中的連線tomcat消費不到,自然沒有機會去響應nginx的關閉socket請求了,這裡留個思考題,如果Acceptor不意外退出,那tomcat在拿到一個處於CLOSE_WAIT狀態的連線會怎麼處理? 

寫在最後

通過一系列的分析最終得出是由於記憶體不足導致tomct的Acceptor執行緒異常退出,進而導致連線堆積在tcp佇列中無法消費,最終引發了兩個問題:

1.新請求一直進不去;

2.大量CLOSE_WAIT狀態的連線存在,而且不會消失。

 

也許有人會問究竟是什麼導致了記憶體不足呢,這裡簡單提一下,之前在提到線上預覽處理流程的時候說過,預覽服務會將附件轉化為html提供給使用者線上預覽,轉化這一步是比較耗記憶體的,有些客戶的附件會達到百兆以上。

 

文中提到了一些非常有用的命令,比如jstack,top,netstat,ss等,之所以沒有花太多篇幅去詳細解釋,一是我對命令的使用經驗有限,二是網路上不乏鋪天蓋地的說明,講的已經很好。

 

通過這篇文章,只是想分享一種排查此類問題的思路,希望你在遇到相似問題的時候帶來些許幫助。

 

推薦閱讀

關於TCP 半連線佇列和全連線佇列 

服務端close-wait或者time-wait狀態過多會導致什麼樣的後果?

PHP升級導致系統負載過高問題分析

淺談CLOSE_WAIT

 

 

 

相關文章