记一次服务Full GC背后的内存泄漏问题，真是匪夷所思

Posted 2023-04-22

参考技术A

最近所负责的服务略频繁地收到4xx告警

1、查业务日志，没发现相关错误的日志
2、查nginx access log，发现返回的状态码都是499，从request_uri查了一遍发现不是集中在某一个请求上，说明应该不是某个接口的问题了，有可能进程层面问题了。

通过对upstream_addr 分类，可以看到问题基本都是集中在 某一台这台机器上

3、网上资料了解到，499 是 nginx 扩展的 4xx 错误，代表客户端请求还未返回时，客户端主动断开连接。原因有几种，不过大部分原因都说到有可能服务器upstream处理过慢，导致用户提前关闭连接。那就先往这个方向排查，登录机器查看实际的access.log

发现upstream response都是10s以上。这就证明了上游服务器处理10秒还没有响应，因此nginx提前关闭链接，返回499

4、为什么进程响应如此慢，10秒太不正常了。考虑到那段时间就只有一台机器有问题，而且是进程层面的问题，首先想到的是GC，于是再次登录到机器上查看gc log。发现有Full GC，时间点和告警的时间也吻合。 惊呆的是，这次FullGC耗时长达19.07秒，由于我们的服务使用的是jdk8默认的ParallelGC，FullGC期间，整个应用Stop The World的。这是非常恐怖的一件事

由此看来，4xx告警的初步原因已经定位到，就是FullGC导致的。

那么究竟为什么会发生FullGC呢？需要深入分析一下。
借助服务治理平台的JVM监控观察了几天。期间不同机器不同时间也发生了几次FullGC。从监控发现，基本每台机器隔两天就会发生一次FullGC，每次FullGC后年老代回收的垃圾不算多，使用比例还是挺高的。

为什么年老代空间占用这么多？

继续分析上面那条full gc log，
1、发生full gc时，年老代内存已经占用了99.98%了（1048397/1048576）。看起来因为年老代满了而触发的FullGC了。
2、full gc回收了年老代大约302M的垃圾，回收后年老代占用70.4%（738282/1048576）。这占用率还是比较高的。

1、首先jmap简单打印一下所有对象的信息。发现有ClassPathList和ClassClassPath两个类的对象数量高达1000多万，并且这两个数量是一样的。仿佛嗅到了内存泄漏的味道。

2、只依靠对象统计信息，不足以定位问题，需要使用完整HeapDump，通过MAT进一步分析

jmap把完整堆heapDump下来

隔一段时间后，继续jmap，这次只取存活对象的dump（实际效果是先执行一次FULL GC）

可以看到，经过Full GC后，ClassPathList对象没有被回收，数量反而继续增加。到这里，基本可以确定，ClassPathList是存在泄漏了。

那么，ClassPathList究竟被谁引用着，导致回收不掉呢？
通过MAT的OQL过滤出老生代的ClassPathList对象，从对象的关联关系上继续深入分析。

首先需要知道老生代的地址区间，可以使用vjtools

通过vjmap的address命令，快速打印各代地址。

可以得知，oldGen的下界是0x80000000，上界是0xc0000000（注意OQL中使用时要把数值前的那串0去掉）。

执行OQL只查询年老代中的ClassPathList对象：执行OQL只查询年老代中的ClassPathList对象：

抽取其中一个对象分析，可以发现这个ClassPathList对象被一连串不同ClassPathList对象的next属性引用着。看起来是个链表的结构

再看看GCRoot，发现是被AppClassLoader也就是我们的应用类加载器引用着。除非这个加载器卸载了，否则ClassPathList对象是不会被GC掉了。

分析到这里，似乎离真相越来越近了。到底这个ClassPathList在项目中哪里使用到了？
通过前面的分析知道了ClassPathList的整体引用关系链：
AppClassLoader -> ClassPool类的defaultPool字段 -> ClassPoolTail类的source字段 -> ClassPathList类的pathList

可以看到，ClassPathList有两个属性，一个是next，结合之前MAT的分析，ClassPathList的确就是一个链表的结构。随着时间的增长，ClassPathList不断新增，链表也随之变得越来越大，最后内存占用逐渐上升。
另一个path字段属于ClassPath类型，ClassPath是个接口，查看它的实现类，发现一个似曾相识的名称ClassClassPath，之前分析对象统计信息时，还有一个类的对象数量是和ClassPathList一样的，正是这个ClassClassPath。每新增一个ClassPathList，都会伴随着新增对应的ClassPath对象，这也解释了为什么两者数量是一致的了。

通过注释知道，这个ClassClassPath的作用大概就是，利用一个叫ClassPool的对象，可以调用其insertClassPath方法来新增一个ClassClassPath对象，insertClassPath方法内部通过头插法将ClassClassPath添加到ClassPathList链表，从而形成一个search-path，然后通过这个search-path能够获取到某一个Class类的信息。

于是尝试着搜了一下，看看项目中有没有调用到insertClassPath方法的地方。意外发现一个类，

这不就是我们项目用来打印方法入参、执行耗时、上报metrics的@AutoLog的实现类吗。

可以看到getParams方法中调用了insertClassPath，注解@AutoLog的printParams默认为true，也就是每次调用都需要打印方法入参，每次打印前都要调用getParams先获取参数名称。因此每次都会insertClassPath，从而导致ClassPathList链表越来越大。

至此，内存泄漏的元凶已经找到。解决方法也就简单了。
因为目标只是想得到方法的参数名称，通过JoinPoint其实能直接获取到，因此可以改成JoinPoint获取的方式。

为了进行对比，分别在修改前后各进行一次压测。压测JVM参数大致与线上一致，为了尽快看到效果，只是调小了heap的大小。-Xms200m -Xmx200m

ClassPathList数量不断增长

年老代每次能回收的垃圾越来越少，每次回收过后的剩余空间也越来越小。最终整个年老代被撑满

虽然还没触发OOM，但是CPU负载飙高，从基本都在处于频繁的FULLGC状态

ClassPathList已经被消灭掉了

FullGC也趋于规律化了。每次回收的垃圾大致都相同

第一种方式是在启动参数增加 -XX:+PrintHeapAtGC，每次GC都打印地址

第二种方式是使用vjmap的命令，在-old, -sur, -address 中，都会打印出该区间的地址

第三种方式，使用vjmap的address命令，快速打印各代地址，不会造成过长时间停顿。

附： 我们服务的JVM参数

记一次 .NET 某外贸Web站 内存泄漏分析

一：背景

1. 讲故事

上周四有位朋友加wx咨询他的程序内存存在一定程度的泄漏，并且无法被GC回收，最终机器内存耗尽，很尴尬。

沟通下来，这位朋友能力还是很不错的，也已经做了初步的dump分析，发现了托管堆上有 10w+ 的 byte[] 数组，并占用了大概 1.1G 的内存，在抽取几个 byte[] 的 gcroot 后发现没有引用，接下来就排查不下去了，虽然知道问题可能在 byte[]，但苦于找不到证据。

以上是关于记一次服务Full GC背后的内存泄漏问题，真是匪夷所思的主要内容，如果未能解决你的问题，请参考以下文章

记一次 CMS GC导致 FULL GC 时间开销很大的排查

记一次 CMS GC导致 FULL GC 时间开销很大的排查

记一次 CMS GC导致 FULL GC 时间开销很大的排查

记一次 CMS GC导致 FULL GC 时间开销很大的排查

记一次 .NET 某外贸Web站 内存泄漏分析

记一次诡异的频繁Full GC