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

時間 2021-04-06

標籤 html java linux nginx 瀏覽器 tomcat 服務器網絡 app socket 欄目 Java 简体版

原文原文鏈接

關鍵詞：TCP、CLOSE_WAIT

問題背景

某日下午有測試人員急匆匆的跑來跟我反饋：「有客戶反饋供應商附件預覽不了，流程阻塞，須要緊急處理」，我立馬精神起來，畢竟都是付費客戶（目前作B端業務，客戶都是付費用戶，不像C端，出了問題發個道歉聲明也就過去了）。html

等她說完，我第一時間用測試帳號登上去驗證，瀏覽器一直在轉圈，差很少一分鐘之後出了nginx的504錯誤頁。java

初步排查

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

504 Gateway Timeout

做爲網關或者代理工做的服務器嘗試執行請求時，未能及時從上游服務器（URI標識出的服務器，例如HTTP、FTP、LDAP）或者輔助服務器（例如DNS）收到響應。nginx

(內容來源於百度百科)瀏覽器

看到這個錯誤碼第一反應就是下游服務太慢，致使nginx請求超時了，這裏的下游服務是自研的附件預覽服務，採用SpringBoot開發，總體的請求鏈路以下圖所示：tomcat

在線預覽的處理流程以下：服務器

1.用戶在業務方站點發起預覽請求；網絡

2.業務方拼接相關參數重定向到預覽服務；app

3.預覽服務經過業務方傳遞的附件連接調用業務方接口下載附件到本地；socket

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等，之因此沒有花太多篇幅去詳細解釋，一是我對命令的使用經驗有限，二是網絡上不乏鋪天蓋地的說明，講的已經很好。

經過這篇文章，只是想分享一種排查此類問題的思路，但願你在遇到類似問題的時候帶來些許幫助。