分享一次排查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等，之因此没有花太多篇幅去详细解释，一是我对命令的使用经验有限，二是网络上不乏铺天盖地的说明，讲的已经很好。

经过这篇文章，只是想分享一种排查此类问题的思路，但愿你在遇到类似问题的时候带来些许帮助。