log4j2 full gc频繁 disruptor 队列 内存泄漏 内存溢出

---

前言

  去年10月份生产环境服务出了点问题，现象是运行一段时间后，full gc非常频繁，从监控上看，基本上每分钟都在执行，本篇博客就纯当记录一下当时的解决过程。

---

一、为什么频繁full gc

  Java 应用频繁发生 Full GC 可能有以下几个常见的原因：

1、内存泄漏：内存泄漏是指程序中的某些对象在不再使用时没有被垃圾回收，导致它们长时间占据内存空间。如果存在内存泄漏，随着时间的推移，堆内存会越来越小，可能导致频繁触发 Full GC。

2、对象创建过多：当应用程序频繁创建大量对象时，会使得堆内存中的空间迅速耗尽。如果要分配的对象无法在堆中找到足够的连续空间进行分配，就会触发一次 Full GC。

3、过度使用 finalize 方法：finalize 方法是 Java 中一个不太常用的机制，它在垃圾回收器回收一个对象之前调用，用于释放该对象持有的资源。但如果 finalize 方法被过度使用，也会导致频繁触发 Full GC。

4、JVM 参数设置不合理：Java 应用启动时需要配置 JVM 参数，包括堆大小、GC 策略等。如果这些参数设置不合理，可能会导致频繁的 Full GC。例如，堆内存设置过小，会导致应用程序频繁触发垃圾回收；GC 策略设置不当，可能会导致 Full GC 耗费过长时间。

  对于一个庞大的工程来说，如果从代码着手，不知道要排查多久，所以我们首要的是获取gc日志和dump文件，查看gc日志可以知道full gc的频次，分析dump文件来定位原因或者先排除不可能的原因。

二、gc日志查看

gc日志如图，由于商业问题，以下数据均为模拟结果：

2022-10-17T00:48:56.955+0800: 975448.799: Application time: 9.8198157 seconds
Heap before GC invocations=6993 (full 97):
……
2022-10-17T00:51:28.544+0800: 975600.389: Application time: 0.8810688 seconds
Heap before GC invocations=6993 (full 114):

这里也顺便讲一下gc日志怎么看，以第一条为例，第二条同理

2022-10-17T00:48:56.955+0800，时间戳，表示此次 GC 调用的时间是在 2022 年 10 月 17 日早上 00:48:56（东八区）。

Application time：9.8198157 seconds，表示应用程序自上次 GC 调用后的运行时间为 9.8198157 秒。

Heap before GC：表示此次 GC 调用前 JVM 堆内存的使用情况。

invocations=6993：表示当前已经执行了 6993 次 GC 调用。

full 97：表示此次 GC 调用是一次 Full GC，JVM 在执行该次 GC 调用时，已经执行了 97 次 Full GC。

975448.799 是 GC 日志中的时间戳，它表示从某个时间点开始到当前时间的秒数（可以理解为时间戳的一个浮点数格式）。在这个例子中，时间戳为 975448.799，意味着该条日志是在程序启动后 975448.799 秒（约为 11 天）时打印的。

从两条日志对比来看，3分钟时间，full gc执行了17次，根据经验来看，full gc一般要几个小时才执行一次（这也和很多因素有关），所以上述频率是一个极不合理的情况。那接下来让我们再分析dump文件。

三、dump文件分析

从dump组成来看，我们大致可以把矛头指向log4j2日志框架了。项目中使用的log4j2版本是2.17.2，队列lmax.disruptor的版本是3.3.4，博主也查看了两个依赖的升级情况，有兴趣的也可以看看，disruptor升级记录，log4j2升级记录，从记录来看，当前版本应该不存在内存泄漏的风险。

既然版本没有问题，那只有可能是设置不当导致的。于是又查了一些相关资料，各位也可以参考一下：
Log4j2的循环队列引起的内存泄露
Log4J日志打印引发的OOM问题排查
记录一次log4j2导致的内存泄漏
根据上述资料，博主调整了环形队列的大小，默认值为256000，调为4096，在应用的启动参数中添加：
-DAsyncLoggerConfig.RingBufferSize=4096，改完后重新压测，发现效果显著，不再出现频繁full gc的问题了。

四、其他配置分析

1、新生代和老年代的比例
新生代和老年代的比例并没有采用默认的3:7，而是手动调整为1:1了，博主在使用默认3:7压测（环形队列依然为256000），这种情况下依赖会出现频繁full gc，生产环境比例一直是1:1，所以考虑风险问题，博主最后也没有改成默认的3:7，如果是新项目，那博主一定采用默认比例，毕竟写jdk的应该比我强太多了。
2、大报文截断
博主还增加了大报文的日志输出截断配置，当报文超过10K时，只打印10K的内容，避免大报文导致内存溢出以及磁盘空间占用太多（大报文一般为base64的图片）。

---

总结

  说到底还是博主太菜了，只知道复制粘贴，导致很多机制都不了解。以上纯当生产问题的处理过程记录，写的不好还请见谅，如果对各位有所帮助，还望点个赞，谢谢。