一次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抓包观察下
