CLOSE_WAIT问题排查
一次 close_wait 问题的深度解析 https://mp.weixin.qq.com/s/miJg4TbVkOjEAQ66eqAx6w
一次 close_wait 问题的深度解析
背景
前些天 QA 同学为保证服务的高可用,为所有线上机器的各项系统指标加了报警,其中就包括了 close_wait 状态的 TCP 连接数报警,结果当天晚上就非常热闹,报警信息、报警电话一波接一波,最后不得不暂时关掉 close_wait 指标报警,后续由各业务线修复了自己的问题之后再重启报警,其中就有几个系统是我们的,几天的探索之后发现是一个非常 low 的问题,本可以快速修复,只因漏看了一行代码,过程中甚至怀疑 apache-httpclient 有 bug,导致了后续花了比较多的精力在上面。虽然如此,回想起问题的排查过程也算颇有收获,所以决定整理一下为自己做个总结,也希望对他人有所帮助。
现象
处于 close_wait 状态的 TCP 连接长期维持在 35 左右,长期处于 close_wait 状态的连接不仅无法提供服务,还会占用 http 客户端和服务端的连接资源,极限情况下导致无法创建连接,严重影响业务。因为之前处理过因为防火墙问题,导致 http 客户端服务器 close_wait 偏高,最终影响给用户退款的 case,所以 close_wait 问题再次出现引起了大家高度重视。以下是出问题是问题机器的 close_wait 监控:
抛出问题
1)TCP 协议是如何工作的,何时会产生 close_wait?
2)TCP 报文发送与 java 代码的关系?
3)为什么会产生 close_wait?
4)close_wait 量为什么每隔一段时间就会断崖式的往下掉?
5)apache httpclient 连接池是如何工作的?
探索之旅
通过报文认识 TCP
首先第一个问题,TCP 协议是如何工作的,主要分三步:
1)三次握手建立连接(下图中 1-3 行)
2)在已建立连接上执行数据传输(下图中 4-7 行)
3)四次挥手关闭连接(下图中 8-11 行)
tcpdump 是分析 TCP 协议的利器,这里我们使用 tcpdump 直接看报文数据来进一步加深理解,下面是通过 tcpdump 工具获取到的一个 TCP 连接整个生命周期的报文(这里先不用关注报文时间,后续会有说明)。
-
17:51:16.801932 IP xxx.xxx.xxx.93.9992> xxx.xxx.xxx.100.36666: Flags[S], seq 3004848363, win 14600, options [mss 1460,nop,nop,sackOK,nop,wscale 9], length 0
-
17:51:16.802069 IP xxx.xxx.xxx.100.36666> xxx.xxx.xxx.93.9992: Flags[S.], seq 2423612252, ack 3004848364, win 14600, options [mss 1460,nop,nop,sackOK,nop,wscale 9], length 0
-
17:51:16.802087 IP xxx.xxx.xxx.93.9992> xxx.xxx.xxx.100.36666: Flags[.], ack 1, win 29, length 0
-
17:51:17.803516 IP xxx.xxx.xxx.93.9992> xxx.xxx.xxx.100.36666: Flags[P.], seq 1:37, ack 1, win 29, length 36
-
17:51:17.803709 IP xxx.xxx.xxx.100.36666> xxx.xxx.xxx.93.9992: Flags[.], ack 37, win 29, length 0
-
17:51:18.804265 IP xxx.xxx.xxx.93.9992> xxx.xxx.xxx.100.36666: Flags[P.], seq 37:65, ack 1, win 29, length 28
-
17:51:18.804462 IP xxx.xxx.xxx.100.36666> xxx.xxx.xxx.93.9992: Flags[.], ack 65, win 29, length 0
-
17:51:19.804768 IP xxx.xxx.xxx.93.9992> xxx.xxx.xxx.100.36666: Flags[F.], seq 65, ack 1, win 29, length 0
-
17:51:19.844675 IP xxx.xxx.xxx.100.36666> xxx.xxx.xxx.93.9992: Flags[.], ack 66, win 29, length 0
-
17:51:22.805256 IP xxx.xxx.xxx.100.36666> xxx.xxx.xxx.93.9992: Flags[F.], seq 1, ack 66, win 29, length 0
-
17:51:22.805280 IP xxx.xxx.xxx.93.9992> xxx.xxx.xxx.100.36666: Flags[.], ack 2, win 29, length 0
要了解 TCP 通讯过程,TCP 标志位不得不提,共 6 位,代表含义如下表,其中除了第一位之外,上面的 case都会用到。
上面是一个典型的TCP三次握手->传输数据->四次挥手的过程,详细过程如下:
第 1 行:第一次握手,93 向 100 发送[S]同步报文,seq=3004848363,创建连接开始
第 2 行:第二次握手,100 向 93 发送同步[S.]同步+确认报文,seq=2423612252,ack=3004848363+1,93tcp 连接状态为 SYNSENT,100 tcp 连接状态为 SYNRCVD
第 3 行:第三次握手,93 发送[S]确认报文,ack=1(网上有些文章说 ack 为2423612252+1 是不对的)连接建立成功
第 4 行:数据传输,93 向 100 发送[P.]数据推送+同步报文,seq=1:37,前闭后开,推送 tcp body 中第 1-36 个字节内容,即 length=36,推送数据为:[05:51:17 802 hello ,i am zhichao.pan],刚好 36 byte
第 5 行:100 向 93 发送[.]数据确认报文,ack=37
第 6 行:同第 4 行
第 7 行:同第 5 行
第 8 行:第一次挥手,93 向 100 发送[F.]主动关闭连接报文,seq=65,ack=1
第 9 行:第二次挥手,100 向 93 发送[.]确认报文,ack 65+1=66
第10 行:第三次挥手,100 向 93 发送[F.]主动关闭连接报文,seq=1,ack=66
第 11 行:第四次挥手,93 向 100 发送[.]确认报文,ack 1+1=2,连接关闭成功
同时伴随以上报文发送,93 和 100 两台机器的 TCP 连接状态如下:
那么 close_wait 何时产生呢?
看上面的 TCP 报文关闭流程可知,当被动关闭方收到主动关闭放 F 报文并回复 ACK 后,TCP 状态为 close_wait,直到被动关闭方发送 F 报文后 close_wait 变更为 LASTACK,理论上这个状态持续的时间非常短,基本很难监控到,除非被动关闭方后续并未立即发起F报文。即只有我们的服务作为被动关闭方未及时发送 F 报文时 close_wait 问题出现,那么如何使用 java 代码关闭 TCP 连接呢?
TCP 报文发送与 java 代码的关系
记一次CLOSE_WAIT问题排查 https://mp.weixin.qq.com/s/nEyaJ9yeyCsMGeb0rvd3SA
记一次CLOSE_WAIT问题排查