本文导读:
- 生产故障场景介绍
- TCP 建连三次握手过程
- TCP 断连四次挥手过程
- 结合 Java 堆栈剖析源码
- 再从堆栈中找到"罪魁祸首"
- 问题优化方案总结
1、生产故障场景介绍
业务简介:
该服务主要是提供对外的代理接口,大部分接口都会调用第三方接口,获取数据后做聚合处理后,提供给客户端使用。
有一天晚上,系统正处于高峰期间,项目组小伙伴正在津津有味的吃着「加班餐」,刚把?塞进嘴里,邮件和短信同时发起来告警。
有一台服务器接口超时,平时偶尔也会收到类似告警,有时会因为网络波动等原因。实在不好意思,没事总让人家「网络」同学背锅 : )。但是,这次告警并没有收敛,持续告警了十几分钟以上,感到了不妙。
点击邮件中告警的 URL 接口链接,一直在页面转圈圈,响应很慢,悲剧!
此刻,默默的把?盒饭推到一边去,不忍直视 :(
问题定位基本流程:
1)确定影响范围
该服务后面挂着多台服务器,仅有一台服务器挂掉了,所以对用户不会有太大的影响。
先临时从注册中心上摘掉,别让客户端继续重试到这台机器上了,保留事故现场。
2)排查监控指标
查看接口服务的访问量,因为是晚高峰,因此会比其他时间段用户访问量会更大些,但是这个访问量看上去跟平时同一时段对比,并没有特别明显突增现象。
监控上观察服务器的 CPU、内存、IO、网络指标看起来也一切正常。
3)服务器排查
登录到服务器上,结合监控进一步查看服务器 CPU、内存 等指标,查看服务日志都是正常的,并且也没有发现特别的异常日志输出,Exception 或者 OOM 等异常。
我们看到的现象是,接口服务已经无法正常响应了,应用跑在 JVM 上,快速通过 JDK 自带的常用命令排查一番了。
如下命令打印堆栈信息:
jstack -l $pid > jstack.log
统计结果如下:
cat jstack.log | grep " java.lang.Thread.State" | sort -nr | uniq -c994 java.lang.Thread.State: WAITING (parking)
501 java.lang.Thread.State: WAITING (on object monitor)
7 java.lang.Thread.State: TIMED_WAITING (sleeping)
13 java.lang.Thread.State: TIMED_WAITING (parking)
2 java.lang.Thread.State: TIMED_WAITING (on object monitor)
23 java.lang.Thread.State: RUNNABLE
如果遇到 java.lang.Thread.State: WAITING (parking)、java.lang.Thread.State: WAITING (on object monitor) 这类线程状态,就要引起注意了,一般可能都是程序本身问题导致的。
根据 java.lang.Thread.State: WAITING 查看 jstack.log 里的堆栈信息,发现了了大量的调用 HttpClient 工具类请求等待挂起的日志,具体堆栈信息待下面详细分析。
这些服务调用都是通过 HttpClient 工具直接调用的,对 Spring RestTemplate 做了一次封装,其底层也是调用的 Apache HttpClient 工具类来实现服务调用的。
除看到上述 jstack 日志异常外,还排查了服务器上的网络状态,这也是运维同学们常用的排查手段。
附上统计网络连接状态的命令:
netstat -n | awk '/^tcp/ {++State[$NF]} END {for(i in State) print i, State[i]}'
统计结果:
TIME_WAIT 9
CLOSE_WAIT 3826
SYN_SENT 2
ESTABLISHED 28
SYN_RECV 8
这里注意了,我们看到服务器诡异的网络连接统计中,出现了大量的 CLOSE_WAIT 状态的连接。
而且这个状态,当你间隔一段时间再次执行统计命令,还是会存在,也就是不会被释放掉了,看上去问题有些严重。
进一步猜测,出现这些 CLOSE_WAIT 状态跟接口响应慢应该是有关系的,同时,也跟 java 堆栈信息中出现的 HttpClient 线程阻塞有关系,作为问题突破口去分析。
不如,我们先来了解下 CLOSE_WAIT 状态,这个 CLOSE_WAIT 状态处于 TCP 网络断开连接过程中,当客户端发起断连请求,服务端首次收到断连请求,回复确认消息,之后便处于 CLOSE_WAIT 状态了,当服务端响应处理完毕会回复网络包给客户端,正常连接会被关闭掉的。
2、 TCP 建连三次握手过程
尽管 CLOSE_WAIT 状态是在 TCP 网络连接四次挥手过程中的。我们还是有必要,先来了解下 TCP 网络连接的三次握手,因为它是请求服务器要做的第一件事情,那就是建立 TCP 连接。
技术源于生活。
我们可以举个日常生活中的例子来理解 TCP 三次握手的过程。
比如你在微信上想与一位很久未曾谋面的朋友聊一聊:
小东:小升,在吗?
(过了很久... ... )
小升: 在了,你还在吗?
(小东刚好在线,天天刷朋友圈... ... )
小东:嗯嗯,在了
(然后两位开始热聊起来... ...)
如果你平时跟朋友,开头总这么聊天是不是觉得很累呢。
其实上面的过程,可以很好的理解 TCP 三次握手的过程。
我们姑且将小东看做是「客户端」,小升看做是「服务端」。 小东是做名 程序员,做 IT 工作。小升在老家开店创业中。理解TCP三次握手过程:
1)小东作为「客户端」,向作为「服务端」的小升发起聊天,就是发送了一个网络包(包签名为 syn
)给小升。【这是 TCP 第一次握手
,小东状态此时处于 syn_sent
状态】
2)小升收到了小东的聊天网络包,你得确认下吧,表示你收到了。此时,小升还有别的事情,不像小东那样搞 IT 工作的,上班还上着微信。到了晚上,小升得空看了一眼手机微信,弹出了小东的消息。然后,激动的做了个回复「 针对小东发来的 sync
包,做了个 ack
回复确认」。因隔了一段时间了,小升也不确定小东还在不在线了。【这是 TCP 第二次握手
,小升状态此时处于 syn_rcvd
状态 】
3)小东因为刚好在线,收到了小升的回复确认消息,马上对这次消息做了一个回复「对着小升给的 sync + ack
,做了进一步 ack
回复确认,这是 TCP 第三次握手
」 。【小升状态此时变成了 established
可马上聊天状态】
4)此时,小升也在线,两位就开始热聊起来了。【正式传输数据了,小东和小升的状态都处于 established
状态】
上述提到的那些状态 syn_sent
syn_rcvd
established
,正是 TCP 三次握手过程中涉及的关键状态。
上一张图来直观理解下:
3、 TCP 断连四次挥手过程
小东和小升的热聊结束了,已经很晚了,也忙了一天了,需要休息了。
小东因工作原因明天要早起,所以提前跟小升说了:
小东:明天要凌晨4点起床升级系统,我要早点休息了,改天过来请你喝酒!
小升:额 ???这样,反正我也不懂!
小升:那你早点休息吧。你说的这顿酒还是要喝的!
小东:嗯嗯,晚安啊!你也早点休息。
小升:好的,晚安,兄弟!
对应理解 TCP 四次挥手过程:
1)小东要休息了,发起了 fin1
包打算结束聊天了。【小东状态此时处于 fin_wait1
状态,这是 TCP 第一次挥手
】
2)小升收到了小东的 fin1
包,回复了 ack
确认消息。【此时,小升状态处于 close_wait
状态,小东此时状态为 fin_wait2
,这是 TCP 第二次挥手
】
3)小升来了一次最后确认,不打算继续聊了,发送了 fin2
包。【此时,小升状态处于 last_ack
状态,这是 TCP 第三次挥手
】
4)小东针对小升发来的 fin2
包,最终回复了个 ack
确认。【此时,小东状态处于 time_wait
状态,这是 TCP 第四次挥手
】
为什么小东还要处于 time_wait
状态等一下呢?
因为他们按照「老规矩」,得确保最后这次消息小升的确收到了,才能最终结束这次聊天。
time_wait
状态标准持续等待时间是** 4
** 分钟,在这段时间内,小东和小升建立的 TCP 网络连接套接字资源(端口),是不能被其他人所使用的,也不能被系统回收重新利用的。
如果小升没有收到反馈,还会继续问下「重发 fin2 消息」,直到小东发送了 ack 消息成功了。
双方正式关闭聊天通道,释放端口资源,连接关闭。
等待的 4 分钟就是 2 个 MSL,每个 MSL 是 2 分钟。MSL就是 maximium segment lifetime——最长报文寿命。这个时间是由官方 RFC 协议规定的。
上一张图,进一步直观理解下:
4、结合 Java 堆栈剖析源码
分析完 TCP 四次挥手过程了,当服务端接收到 TCP 断开连接的请求包,需要回复一个确认消息给客户端,此时服务端状态便处于 CLO