记一次服务端内存泄漏排查之旅（第二篇）

目录

      一、事故背景

      二、线上排查

      三、代码分析定位、本地测试验证

      四、问题确认

      五、问题修复

      六、思考启发

---

一、事故背景

本次线上内存泄漏表现出来(接到报警通知)是在上上周末，当大家都沉浸在周末的闲暇时光的时候

，突然工作群接到运维通知说监控到我们的服务爆出一些500的错误，一时间，小组哗然，大家忙着看各种监控指标是否正常，发现内存大量被占用，居高不下释放不掉，cup持续飙高，接口耗时也非常严重。

基于第一时间恢复线上可用的原则，我们临时对线上服务进行了手动发布部署，先让线上恢复了正常，而且一段时间内都没有问题之后，先暂时记录下诸多个异常点及数据，以便后续排查。

二、线上排查

到了工作日我就基于周末问题点考虑开始着手进行排查、优化，先进行了简单的猜想：内存飙高、释放不掉一般来说有可能是创建了比较大的对象，或者是创建了无用的对象，或者是代码有复杂冗余逻辑、更甚者是有内存泄漏问题。于是查看监控，找到流量较高的TOP接口，先看了下代码逻辑，确实有一些上面的某些问题，就先进行了一波代码逻辑优化，但是，这些代码问题点并不能说服自己，因为即使有这些问题点存在，绝对不会造成线上如此严重的问题呀。

此时，当我再次查看各种监控数据的时候，发现比周末平稳许多，但是比正常的时候看得出还是有一些异常，只是不是特别明显，猜想其实就是跟流量有关系，当流量比较平稳的时候，此时问题肯定表现不出来，看了下实时流量QPS的确不高。

但是，既然周末在某个时间点暴露出来严重的问题，事出必有因，于是开始对线上进行排查，期望能够揪出背后的罪魁祸首。

因为是在工作日，数据异常表象不像是周末那么明显，为了便于排查问题，通过监控我找到了一台当时数据异常表象比其他服务器明显的服务器，登录进控制台，首先使用top命令查看CPU情况

可观测到此时CPU和内存占用，已经表现很明显了。

首先使用jps命令找出应用服务的进程id为1。

jps -l

对于CPU使用率上升，我首先使用了jstack命令查看了jvm线程信息。

jstack  -l  1 > /data/logs/jstack.log

将线程信息dump到jstack.log文件中，使用vi命令打开文件，由于jstack.log文件线程信息比较多，需要我们仔细看线程数量、状态等信息， 通过查看这个文件我发现除了tomcat、redisson、nacos线程池外，其他的线程池基本上都是我们业务中创建的线程池，而且线程池比较多，自定义线程池8个加上hystrix2个，一共使用了10个线程池，这明显创建的太多了，而且通过监控数据来看，很多线程都是处于watiing、time_waiting状态，使用率并不高，白白消耗CPU的调度资源，除此之外，在线程文件中并没有发现其他有用的信息，于是接下来开始进行了jvm垃圾回收、内存数据变化的观测。

使用jstat命令每2秒一次显示进程号为1的java进程垃圾回收统计情况，打印10次，结果如下图

jstat -gcutil 1 2000 10

从这些jvm垃圾回收次数和数据增长数据来看，很明显能够看出Eden区数据增加非常快，并且很快就被晋升到了老年代，老年代增长的也比较快，不断地在触发fullgc，从其他监控数据来看，在周末，每分钟要进行接近30次的gc(ygc&fgc)，而且gc时间都比较长，也就是说几乎所有的时间都在进行垃圾回收，然后就会造成用户空间线程阻塞，接口响应大大下降，甚至超时。于是接下来我企图通过其他方式期望找到是哪些接口、创建的什么样的对象造成如此快的对象创建甚至内存释放不掉。

如果直接使用jmap命令只能看jvm各个分区内存使用大小及使用率变化情况，还是看不到更加细粒度的对象行为，于是我使用jmap -histo期望看到对象实例数量及大小的变化情况。

jmap -histo 1 | head -30

使用jmap -histo默认按照占用内存大小降序排序，取TOP30个实例进行查看。

命令执行完成后，得到的是这样的一个jvm实例快照数据，很显然从某个时刻的快照数据并看不出很明显的问题，有可能某个时刻对象就是创建了很多，随即就会被jvm垃圾回收了，也就是说我们需要看的是实时动态的数据变化，于是我手动执行了几次同样的这个命令，结果却让我眼前一亮。

通过不断地执行这个命令，查看动态实时数据变化，我发现两个现象：

①、$1这个内部类一直在递增，并没有被回收而释放掉，其他的对象实例都会在某一瞬间被jvm垃圾回收掉。

②、[Ljava.lang.Object; 这个Object对象变化速率非常快，也就是说相隔很短的时间就会被释放掉，而且，实例数量和占用内存都不小。

至此，通过这些数据现象来看，极有可能发生了内存泄漏，于是，接下来，基于已知的这些问题，带着疑问，看了一下项目源代码。

三、代码分析定位、本地测试验证

我复制了$1这个内部类的类全限定类名，在项目中找到这个类，发现这个内部类是我们接入线程池监控时使用到的一个内部类，用来收集线程池的参数信息。

于是，接下来对StatusExtensionRegister.getInstance().register()进行了代码逻辑查看，发现每次调用register()方法，都会把新创建的内部类add()到StatusExtensionRegister.getInstance()这个类中的集合中去。

而且，跟了下List<StatusExtension> extensions这个集合在源代码中的使用情况，发现并没有在其他地方对这个集合中的元素进行删除，然后本地准备好环境启动服务进行了验证，结果发现确实这个内部类在不断地进行创建，并没有在任何时机回收它。

四、问题确认

从项目源代码来看，这个接入的时机是获取到我们自定义线程池每次执行execute()执行线程任务的时候，只要使用到我们自定义线程池，执行一次，就会创建一个内部类，扔到extensions这个集合中去，而extensions这个集合正因为有类静态属性引用，被GCRoot强引用，所以一直释放不掉，从当前观测的数据来看，我大致计算了一下，这个内部类每小时净增量0.44M，从服务重启到现在时间是98个小时，98*0.44=43.12M，目前服务里面这个内部类整体占用46M，基本上相差不多，这是按照平均计算，3M的差异应该和流量有关，目前这个内部类还在递增，只不过流量很小，增势不明显而已，如果一旦遇到流量高峰，那么项目基本上就扛不住了，至此，从jvm内存数据现象和推算数据来看，已经确定了这个内存泄漏点。

五、问题修复

再次仔细分析了这个线程池监控的接入方式，发现应该在我们自定义线程池创建的时候进行接入、创建这个内部类就行了，进行线程池名称、参数的收集，后续，会有第三方包中的异步线程定时对extensions这个集合中的线程池轮询进行监控，信息上报。

六、思考启发

其实除了内存泄漏，这次线上故障也暴露出来了其他的问题，在这里就不再赘述，我们经历这次事件也做出了几点总结：

①、项目代码仍需要定期review，找出优化点。

②、中间件接入时候需要全面调研，必要时下载源码，搞懂原理。

③、继续进行现有监控体系建设，如果出现任何问题，监控看板会及时发送提醒，为排查类似问题提供线索，快速定位类似问题。

以上是个人的亲身经历及总结经验，个人之见，难免考虑不全，如果大家有更好的建议欢迎大家私信留言。如果对大家有一点点帮助，麻烦动动小手赞个赞也是对我的鼓励和支持。

更多分享请移步至个人公众号，谢谢支持😜😜......

公众号：wenyixicodedog