问题备忘: httpclient连接池异常引发的惨案

正文

1. 问题描述

客户端A –> Ngnix –> 服务B Ngnix做服务B的负载，客户端访问服务B时，客户端偶尔会有抛出TimeoutException异常。

举个例子：如A在09:59:48访问B，则服务B在09:59:53收到请求，并成功执行业务并返回。但是A会在10:00:05左右抛出TimeoutException。此时客户端A认为本次调用失败，然后走失败的业务逻辑。但是查找服务端的日志，发现实际业务在服务B上正常执行了，并正常返回。这样出现客户端和服务端两边数据不一致的问题。

这个问题是难点：

1. 两边是通过公网调用，公网网络的复杂性会导致问题更复杂
2. 无法直接定位是服务端还是客户端的问题
3. 两边的程序不是同一个所写，由不同人维护。自己维护服务端代码，客户端代码是其它人维护
4. 需要理解TCP/IP的通信协议
5. 需要理解httplclent和ngnix的超时配置相关的知识

下面我按照以下顺序一一排查问题：

1. 网络问题
2. 超时配置参数的问题
3. GC的问题
4. 使用tcpdump抓包，分析网络包
5. 修正代码问题
6. 上线验证

2. 问题分析处理的过程

2.1. 网络问题

由于客户端A和服务B是使用公网访问，最开始认为是网络抖动引起，并没有马上处理。但是运行一段时间后且这段时间服务器的流量不是很大，这个问题仍然每天不定时出现，所以猜测可能不是网络的问题。

2.2. 超时配置参数的问题

又猜测可能是超时参数配置的问题。整理服务端和客户端配置如下：
客户端httpclient
客户端httpclient的关于连接的配置相关的参数和意义如下：

• SocketTimeout 是 5s
  
  • 连接建立时间，即三次握手完成时间
• ConnectTimeout 是 3s
  
  • 连接建立后，数据传输过程中数据包之间间隔的最大时间
• ConnectionRequestTimeout 是默认值
  
  • httpclient使用连接池来管理连接，这个时间就是从连接池获取连接的超时时间

这3个属性的关系如下：下图来自网络

虽然报文(“abc”)返回总共用了6秒，如果SocketTimeout设置成5秒，实际程序执行的时候是不会抛出java.net.SocketTimeoutException: Read timed out异常的。
因为SocketTimeout的值表示的是“a”、”b”、”c”这三个报文，每两个相邻的报文的间隔时间没有能超过SocketTimeout。

ngnix端
ngnix端的超时相关的配置如下

1. keepalive_timeout 10;
2. send_timeout 60;

经过对以上配置参数的深入理解，再加上即使异常的请求服务端也有收到请求并正常执行业务，且每个请求处理完毕的时间都在100ms左右。总之即使以上的配置参数异常导致超时也跟这个问题的现象不同，所以初步排除配置异常的问题

2.3. GC的问题

请教组内的同事，可能是GC的问题，可能是GC的关系使服务暂停运行没有及时处理业务
在服务端B执行如下命令，发现没有执行过FGC，YGC的时间也是在合理范围内
jstat -gc pid 2000 20

在客户端A执行如下命令，发现其频繁执行FCG，YGC
jstat -gc pid 2000 20
使用”jmap -heap pid” 查看客户端A的堆的分配情况，发现其内存分配非常小，老年期的已用空间在96%以上。
综上，我们认为是在httpclient建立连接后，堆内存不足引发频繁的FGC，使得httpclient的无法在及时将数据发送请求到服务端，偶尔出现在5s临界点才发送数据到服务端成功
修改堆内存后，GC的问题解决了，但是很遗憾，这个问题没有被修正。

2.4. 使用tcpdump抓包，分析网络包

最后使出大招，在服务端172.23.4.33端使用tcpdump抓包，内容如下：

蓝色框的部分 ：之前有一个正常的请求，通信完毕后10s，ngnix由于keep-alive=10s时间到了，发送请求通知关闭连接 close notify信令。但是这里有个问题，这里服务端发送FIN信令，而客户端没有发送FIN信令，不符合标准的TCP的四次挥手协议。即连接在服务端已经关闭，而客户端没有关闭。

这里的Alert (level warning description close notify)：表示发送方会关闭这个连接，不会在这个连接上发送任何数据

红色框的部分

请到「今天看啥」查看全文