服务假死问题解决过程实记（一）——问题发现篇
作者：互联网
一、前言
自三月六日起，笔者所在业务组的开发环境上出现了若干次服务假死，页面请求无响应的现象。由于笔者在三月六日之前，对 JVM, Tomcat，以及数据库连接池没有丝毫调优经验，所以从三月六日开始的所有与解决该问题的过程，都会记录到本文，以记录并纪念笔者的第一次服务调优经历。
链接：
《服务假死问题解决过程实记（一）——问题发现篇》
《服务假死问题解决过程实记（二）——C3P0 数据库连接池配置引发的血案》
《服务假死问题解决过程实记（三）——缓存问题优化》
二、03.06 记 Tomcat 的一次假死问题解决经历
注：
- 本文是一个前序，记录问题出现的现象，以及猜测的原因。本文中最后猜测出现的结论，并非服务假死的原因所在。
- 2019.03.30 记，该现象的源头是因为 C3P0 参数配置问题，现已解决该数据库连接问题。但这只是问题解决过程中顺手解决的另一个问题而已，服务假死的原因应该是因为其他原因，该问题并非源头。
1. 测试环境服务假死
现象：未知具体操作，但出现 Tomcat 假死情况，无法使用 jmap, jstat, jstack 指令以及 jvisualVM 工具，且使用 netstat -ano | findstr “12808” 指令后，出现七八个 CLOSE_WAIT 连接。
猜测原因：
- ClassLoader 的更换，导致方法区溢出？
- 反射使用太多？
待解决方法：
- 重启服务，待正常运行过程中使用 JVisualVM 监控，看方法区以及堆区的大小变化；
- 如果还需要重新启动服务，加入虚拟机 GC 参数：-XX:HeapDumpOnOutOfMemoryError；
- 如果确定是 ClassLoader 堆积的问题，则加入类卸载参数：-Xnoclassgc；
相关参考连接：
- 关于 CLOSE_WAIT 状态，来自于关闭 TCP 连接的四次握手：
2. 再次假死，并成功定位问题
由于昨天有了一次假死，且假死过程中已经不能使用 JVisualVM 连接 Tomcat 服务，所以在服务重启之前，我就已经打开了 JVisualVM 远程监控。但到了下午 17:24 再次假死。
(1) 第一个排查方向：方法区与堆内存
师父一直怀疑是因为业务原因，使用过自定义的 ClassLoader，并存在稍微频繁加载类的可能性，所以他的检测重点在于方法区。但开 JVisualVM 发现方法区大小一直稳定在 150+M，从始至终很稳定的很小幅度增长，远没有到我们设置的 MaxPermSize = 500M。此外给虚拟机设置的 -Xmx:4096M，但实际使用堆内存只有 800M 左右。
(2) 第二个重点排查方向：激增的线程数量
我的监控重点，在于观察到 17:24 线程数飙升，从 240 个线程瞬间涨到了 400+ 个。打开 JVisualVM 的线程监控界面，发现几乎同一时间 pool-22, pool-37 创建了大量线程。使用线程 Dump，读取 Dump 文件，发现大部分 BLOCK 的线程都是汇总数据的内容，以及在 save, update, delete 方法上加的 After AOP 中的异步日志记录方法。所以线程暴增的原因，肯定和 17:24 出现的某种 save 操作有关。果然在我写的记录 save 方法操作记录的日志文件，结合项目日志，了解到 17:24 分有测试人员调用 XML 解析入库的方法，且调用了十几种不同的表的插入操作，估算了一下自己写的代码，大概一次 save 操作应该会加入十一二个 task 到阻塞任务队列中，所以线程数量暴增的问题定位到了。
但是，**以前测试人员也做过很多次类似的解析 XML 入库的操作，并没有引发过 Tomcat 假死的错误。**我感觉很奇怪，所以还是只把线程数量激增的情况当成了一种现象，并未完全它是问题的源头。
(3) 第三个重点排查方向：CLOSE_WAIT 数量
上网搜 “Tomcat 假死”，帖子 《tomcat假死之谜？》 介绍，会出现 100+ 个 CLOSE_WAIT 的现象，导致了 Tomcat 崩溃。那时候老子还不会使用 netstat 指令，甚至连 CLOSE_WAIT 都是前一天晚上临时抱佛脚学的，就依葫芦画瓢输了个 netstat -ano | findstr “CLOSE_WAIT”，结果出现只有 10 个左右的 CLOSE_WAIT 是和我们的服务有关的，虽然有了找到错误的那么点儿意思，但 10 个 CLOSE_WAIT 也太没牌面了吧……
(4) 第四个重点排查方向：TIME_WAIT 数量
大概有一个多小时纠结在 CLOSE_WAIT 上面，后来还是尝试着按照帖子的做法来做，开始监控 TIME_WAIT。改了个 netstat 指令：netstat -ano | findstr “TIME_WAIT”。结果发现有 200+ 个 TIME_WAIT！！
”终于上量级了！！有牌面了啊妈蛋！！“——笔者的内心世界
TIME_WAIT 的内容是啥呢？大致内容都是：
......
tcp 16.12.104.133:55177 16.12.181.151:1521 TIME_WAIT
tcp 16.12.104.133:56430 16.12.181.151:1521 TIME_WAIT
tcp 16.12.104.133:55659 16.12.181.151:1521 TIME_WAIT
tcp 16.12.104.133:55141 16.12.181.151:1521 TIME_WAIT
tcp 16.12.104.133:56582 16.12.181.151:1521 TIME_WAIT
tcp 16.12.104.133:55240 16.12.181.151:1521 TIME_WAIT
tcp 16.12.104.133:54811 16.12.181.151:1521 TIME_WAIT
tcp 16.12.104.133:55772 16.12.181.151:1521 TIME_WAIT
......
重点来了，虽然不懂 TIME_WAIT，但**大片的 1521** 也太醒目了吧啊喂！！
1521 是确实是 Oracle 默认的连接端口号，而且对应的 16.12.181.151 也确实是我们要连的数据库，但是我们的服务又不是直连数据库的，怎么会出现这么多的 1521 端口的 TIME_WAIT 呢？莫非是 RPC？不对，我们的 RPC 应该是直连 DAO 服务的，DAO 服务才会连接数据库，所以肯定也不会是 RPC 的原因。
忽然我想到了一个很重要的事情：由于我们的资源有限，只分配了两台虚拟机，对于我们这个有四个服务 (两个应用服务，两个 DAO 服务) 的业务组，我们把应用服务和 DAO 服务交叉配置，所以在我们服务部署的 16.12.104.133 虚拟机上，确实是有一个 DAO 服务的，而且和我们的应用服务部署在同一个 Tomcat 下！
(5) 确定问题所在的证据
**首先，我先检查其他业务组的正常 DAO 服务。**远程连到其他正常 DAO 服务的虚拟机上输入同样的指令 netstat -ano | findstr “TIME_WAIT”，以及 netstat -ano | findstr “CLOSE_WAIT”，都不会出现几行。所以可以确定这个 DAO 服务肯定是有异常的。
然后，端口数量。还是刚才 16.12.133.104 上连接数据库的端口数，是很明显的 +1 递增趋势，最大的端口数基本上是 65400+ 左右。我专门查了一下端口最大连接数量，知道了 TCP 最大连接数量是 65536 个，所以这种占据了大量端口的现象，一定是异常！！
确认了异常的原因，是**部署在 16.12.104.133 上同 Tomcat 下的 DAO 层服务的数据库连接异常**。这样也可以解释，为什么 JVM 监控正常，GC 情况无异常，且在假死现象出现后甚至无法使用 JVisualVM 连接服务的诸多情况都可以解释了。
注：
值得一说的是，对于基于 TCP 的 HTTP 协议，关闭 TCP 连接的是 Server 端，这样，Server 端会进入 TIME_WAIT 状态，可想而知，对于访问量大的 Web Server，会存在大量的 TIME_WAIT 状态，假如 server 一秒钟接收 1000 个请求，那么就会积压 240*1000=240000 个 TIME_WAIT 的记录，维护这些状态给 Server 带来负担。当然现代操作系统都会用快速的查找算法来管理这些 TIME_WAIT，所以对于新的 TCP 连接请求，判断是否 hit 中一个 TIME_WAIT 不会太费时间，但是有这么多状态要维护总是不好。
HTTP 协议 1.1 版规定 default 行为是 Keep-Alive，也就是会重用 TCP 连接传输多个 request/response，一个主要原因就是发现了这个问题。
未完待续。下篇《服务假死问题解决过程实记（二）——C3P0 数据库连接池配置引发的血案》
标签：16.12,服务,实记,假死,问题,1521,TIME,WAIT 来源： https://blog.csdn.net/ajianyingxiaoqinghan/article/details/89736329