分享一次排查CLOSE_WAIT过多的经验

关键词：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