服务假死问题解决过程实记(一)——问题发现篇

一、前言

自三月六日起,笔者所在业务组的开发环境上出现了若干次服务假死,页面请求无响应的现象。由于笔者在三月六日之前,对 JVM, Tomcat,以及数据库连接池没有丝毫调优经验,所以从三月六日开始的所有与解决该问题的过程,都会记录到本文,以记录并纪念笔者的第一次服务调优经历。

链接:

《服务假死问题解决过程实记(一)——问题发现篇》
《服务假死问题解决过程实记(二)——C3P0 数据库连接池配置引发的血案》
《服务假死问题解决过程实记(三)——缓存问题优化》

二、03.06 记 Tomcat 的一次假死问题解决经历

注:

  1. 本文是一个前序,记录问题出现的现象,以及猜测的原因。本文中最后猜测出现的结论,并非服务假死的原因所在。
  2. 2019.03.30 记,该现象的源头是因为 C3P0 参数配置问题,现已解决该数据库连接问题。但这只是问题解决过程中顺手解决的另一个问题而已,服务假死的原因应该是因为其他原因,该问题并非源头。

1. 测试环境服务假死

现象:未知具体操作,但出现 Tomcat 假死情况,无法使用 jmap, jstat, jstack 指令以及 jvisualVM 工具,且使用 netstat -ano | findstr “12808” 指令后,出现七八个 CLOSE_WAIT 连接。

猜测原因:

  1. ClassLoader 的更换,导致方法区溢出?
  2. 反射使用太多?

待解决方法:

  1. 重启服务,待正常运行过程中使用 JVisualVM 监控,看方法区以及堆区的大小变化;
  2. 如果还需要重新启动服务,加入虚拟机 GC 参数:-XX:HeapDumpOnOutOfMemoryError;
  3. 如果确定是 ClassLoader 堆积的问题,则加入类卸载参数:-Xnoclassgc;

相关参考连接:

  1. 关于 CLOSE_WAIT 状态,来自于关闭 TCP 连接的四次握手:
  1. 《netstat监控大量ESTABLISHED连接数和TIME_WAIT连接数题解决》

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.104.133 上连接数据库的端口数,是很明显的 +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 数据库连接池配置引发的血案》

已标记关键词 清除标记
相关推荐
©️2020 CSDN 皮肤主题: 大白 设计师:CSDN官方博客 返回首页