一次资源泄露问题排查纪录

问题背景

前不久技术学院负责人让我帮助维护下⼤讲堂、积分管理等⼏个系统。这些系统功能都已经很稳定，也不会再有新的功能开发，但是⼤讲堂系统自上线后，每过⼀段时间就会出错，导致学员⽆法报名课程，希望我帮助解决下。这种累积下来的问题解决起来⽐较难，但是对能⼒提升帮助很大，我欣然接受了，所以就有了这次“艰苦”的问题排查和解决之旅。

解决思路

本人未参加过大讲堂和积分系统的开发，解决问题⾸先要最⼤化的了解系统背景、问题发⽣时的系统表现等信息。技术学院的同事和我说，负责系统的开发⼈员已经换过⼏波了，现在基本已经找不到了解系统的开发⼈员了，但是也反馈了以下信息：
1、系统是16年公司应届⽣培训时做的项⽬。
2、其他系统运⾏良好，就是⼤讲堂系统偶尔会报错，导致学员⽆法报名，重启下就好了，果然是“重启⼤法”好啊。
3、系统出错的频率不⾼，但是貌似很有规律，⼤半个⽉左右出现⼀次。
根据以上描述，特别是出错后“重启⼤法”特别有效，出错频率基本固定，通过这两点基本上可以断定是资源泄露导致的问题。既然确定是资源泄露问题，对于 Java 应⽤来说排查⽅向也就确定为以下2个⽅向：
1、对象泄露
2、线程泄露
3. 处理过程
前文提过本人并未参与项目开发，所以整个排查大部分是通过 linux 和 jvm 的⼀些命令行辅助功能来进行的，下面是整个排查过程：
1、 首先通过 jps 确定 Java 应用的进程 id

sudo -u tomcat jps -lv | grep qtscore

2、 排查内存泄露

通过持续观察 GC 日志文件 /home/q/www/qtscore/log/gc.log 文件，发现 GC 执行频率正常，特别是 Full GC 执行也并不频繁，虽然内存使用量在持续增长，但是并不明显。

为了确认业务代码是否存在泄漏，通过 jmap 查看了堆内对象分布情况，切记此命令会导致进程暂停，如果是 qps 高或者响应时间要求高的应用慎用：

sudo -u tomcat jmap –F -histo 11035

存泄露的可能性。
3、 排查线程泄露

top -H -p 11035

通过结果可以看出线程已经高达4038，应用中dubbo线程池默认配置是200个线程，tomcat线程池配置也是200个线程，所以这个线程数明显不合理。参照另外一个同等应用，其线程数未超过500，所以可以初步判断系统存在线程泄露，下⼀步只能查看线程栈信息了：

sudo -u tomcat jstack -l 11035 > /tmp/qtscore_stack.log

系统中存在100多个“New I/O boss"线程，这个应该是 netty 线程池的 boss 线程，到这里基本上可以确认是线程池泄露引起的问题了，但是究竟是哪段代码引起的，线程栈中并无业务相关代码，只是 netty 线程池的代码，所以无法判断出引起问题的代码源头，只能先看看系统日志中是否有价值的信息了，发现系统日志中频繁报以下错误：

找到对应的源代码进行查看，发现这是⼀个 dubbo 服务接口，而 dubbo 底层用的就是 netty，种种迹象表明问题应该就出在这里。仔细分析代码后，发现这个 dubbo 接口抛出的异常 QtalkQueryException，居然没有通过 api 暴露给调用方，也就是说调用方是无法正确反序列化这个异常的。初步推测可能就是这个原因导致 dubbo 未能正确处理线程池，导致线程池泄露了。将 QtalkQueryException 改为抛出 IllegalStateException 异常，发布上线，满怀期待地等着问题被完美解决。过了一个星期后，通过 top 命令查看进程的线程数，发现线程数又飙升到1千1百多了，看来问题还是没有解决，只能再排查了，但是基本上可以确定是线程泄露问题，而且是 netty 引起的，可是线程栈中 netty 的 worker 线程栈中没有任何业务相关的代码，应该是代码间接用到了 netty 线程池，但是一时没有了头绪。只有找同事咨询一下了，和几个同事讨论后，大家都认为最有可能用到线程池的就是异步请求，特别是一些HTTP客户端，根据这个思路对代码进行排查后，发现系统中有如下代码：

这个 com.ning.http.client.AsyncHttpClient 底层用到了 netty 线程池，这个用法存在明显错误，AsyncHttpClient 实例应该重用，而不应该每次使用时都创建一个。修改代码后重新发布上线，一周后再统计应用线程数，发现线程数稳定在350个左右，确认问题得到了解决。但是故事还没有结束，个人觉得既然应用报错，日志应该有所体现才对，难道是被其他异常淹没了？所以重新排查了出错日期的日志，果然发现了以下错误信息：