一、前言
自三月六日起，笔者所在业务组的开发环境上出现了若干次服务假死，页面请求无响应的现象。由于笔者在三月六日之前，对 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，一个主要原因就是发现了这个问题。
网友评论