一次HTTP connect-timeout的排查(上)

问题描述

公司的支付系统，支付核心调用网关系统时候，Tomcat接口服务偶尔会出现连接超时，以下为问题现象：

出现连接超时的时间点，该机器仍有正常的请求到网关系统，只是部分请求异常
偶发性质，一天或2天一次，且出现连接超时的时间段比较短暂

image.png

初步排查分析

JVM GC情况：正常，分析GC日志，在发生连接超时时间段，系统只发生过几次YGC，每次STW时间在0.02 sec 左右
系统资源：CPU、I/O、磁盘使用率和平常一样，无异常
Tomcat 线程数：在出现连接超时的时间段，活动线程数增长了100多个，当仍远低于1500最大工作线程数。
检查网络，发下在出现连接超时的时间段，TCP全连接队列发生了溢出

image.png

PS：只是临时找了个类似的图，当时时间的溢出图没找着

基于以上分析，初步怀疑是TCP全连接队列溢出导致出现了客户端连接超时的情况
接着查看溢出后，OS怎么处理：

# cat /proc/sys/net/ipv4/tcp_abort_on_overflow
0

tcp_abort_on_overflow 为0表示如果三次握手第三步的时候全连接队列满了那么server扔掉client 发过来的ack（在server端认为连接还没建立起来）

接着检查服务端的全连接队列长度，发现仅为100。而出现连接超时情况时，全连接队列已经堆积了超过100个请求

采用ss -lnt | grep {server_port} 查看
[root@localhost ~]# ss -lnt | grep 10007
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 100 :::10007 :::*

解释一下上诉Recv-Q Send-Q的含义：

LISTEN 状态: Recv-Q 表示的当前等待服务端调用 accept 完成三次握手的 listen backlog 数值，也就是说，当客户端通过 connect() 去连接正在 listen() 的服务端时，这些连接会一直处于这个 queue 里面直到被服务端 accept()；Send-Q 表示的则是最大的 listen backlog 数值
非LISTEN状态:
recv-Q 表示网络接收队列，表示收到的数据已经在本地接收缓冲，但是还有多少没有被进程取走
send-Q 表示网路发送队列
对方没有收到的数据或者说没有Ack的,还是本地缓冲区.
如果发送队列Send-Q不能很快的清零，可能是有应用向外发送数据包过快，或者是对方接收数据包不够快。

检查tomcat的配置的backlog，确实默认的是100，关键代码如下：

   NioEndpoint.java
   serverSock.socket().bind(addr,getAcceptCount());
   /**
     * Allows the server developer to specify the acceptCount (backlog) that
     * should be used for server sockets. By default, this value
     * is 100.
     */
    private int acceptCount = 100;
    public void setAcceptCount(int acceptCount) { if (acceptCount > 0) this.acceptCount = acceptCount; }
    public int getAcceptCount() { return acceptCount; }

测试模拟

经过上诉分析，已经初步怀疑是由于tomcat backlog配置过小导致的客户端出现连接超时，在测试环境进行模拟（系统TCP相关参数与生产环境一致）

将tomcat的backlog配置调小至1：(max-connections默认10000，max-threads默认1500)

-Dserver.tomcat.accept-count=1

服务端接口：

    @ResponseBody
    @RequestMapping("/tomcatTest/{sleepSeconds}")
    public String testSMS(@PathVariable("sleepSeconds") long sleepMS) {
        try {
            TimeUnit.SECONDS.sleep(sleepMS);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        return "OK";
    }

并发10个http请求（连接超时时间配置为3s，服务端处理时长为10s），出现3个连接超时的情况

第3次异常:I/O error on GET request for "http://xxxx:19966/tomcatTest/10": connect timed out; nested exception is java.net.SocketTimeoutException: connect timed out exec: 3001
第5次异常:I/O error on GET request for "http://xxxx:19966/tomcatTest/10": connect timed out; nested exception is java.net.SocketTimeoutException: connect timed out exec: 3001
第4次异常:I/O error on GET request for "http://xxxx:19966/tomcatTest/10": connect timed out; nested exception is java.net.SocketTimeoutException: connect timed out exec: 3003
第0次正常 exec: 10020
第1次正常 exec: 10019
第7次正常 exec: 10018
第2次正常 exec: 10023
第9次正常 exec: 10020
第8次正常 exec: 10022
第6次正常 exec: 10327

在执行期间观察全连接队列情况，确实有出现溢出

netstat -s | grep -i "listen"
366 times the listen queue of a socket overflowed
366 SYNs to LISTEN sockets ignored

netstat -s | grep -i "listen"
368 times the listen queue of a socket overflowed
368 SYNs to LISTEN sockets ignored

将tomcat backlog调大后，在继续压测，没有在出现连接超时的情况。
依此测试结果，将线上的tomcat backlog增大至500后，观察一周均无在出现connect timeout的情况。

未完待续

疑惑1：按道理全连接队列满了，但是客户端的连接请求是已经接收到SYN+ACK了，所以对于客户端来说该连接已经建立了，为啥会报connect timeout ? 应该是read timeout或者connect reset 。
疑惑2：全连接队列满了，但客户端的请求认为连接ESTABLISH状态，可以继续发送数据请求。这时候服务端如何处理？
带着这2个问题，后续将会模拟测试全连接队列满的情况，通过TCPDUMP抓包观察下