记一次疑似JVM内存泄漏的排查过程

2024-06-16 15:06

背景

在今年的敏捷团队建设中，我通过Suite执行器实现了一键自动化单元测试。Juint除了Suite执行器还有哪些执行器呢？由此我的Runner探索之旅开始了！

在日常部门OpsReview过程中，部门内多次遇到应用容器所在的宿主机磁盘繁忙导致的接口响应缓慢，TP99增高等影响服务性能的问题，其中比较有效的解决方案是开启日志的异步打印，可以有效避免同步日志打印在磁盘IO高起的情况下拖慢业务线程的执行效率。

部门内的jimkv应用为了配合仓做切量，在最近将日志打印功能降到了INFO级别，打开日志打印以便问题排查，期间遇到过一次因宿主机磁盘繁忙引起TP99升高导致多个comsumer超时而影响了个别业务。

经过评估遂对组内的两个基础应用（pk和jimkv）切换为异步日志打印功能，在pk上线一周后观察无异常情况后对jimkv也同样切换。

具体切换方法为在项目里和log4j2.xml同级目录下创建log4j2.component.properties文件，配置如下：

# 所有Logger异步配置log4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector# 日志队列满的处理策略，丢弃log4j2.asyncQueueFullPolicy=Discard# 丢弃日志的级别log4j2.discardThreshold=ERROR

但是在jimkv开启3天后收到了JVM内存使用率超高的告警电话，担心会发生OOM而且时值周五晚就先将所有机器重启了一遍，最后一台执行jmap dump等命令来保留现场以备后续排查。

现象

理解，首先 MCube 会依据模板缓存状态判断是否需要网络获取最新模板，当获取到模板后进行模板加载，加载阶段会将产物转换为视图树的结构，转换完成后将通过表达式引擎解析表达式并取得正确的值，通过事件解析引擎解析用户自定义事件并完成事件的绑定，完成解析赋值以及事件绑定后进行视图的渲染，最终将

2.1 容器和JVM配置

容器硬件配置：4C8G

JVM配置：-Xss256k -Xms4G -Xmx4G -XX:MaxMetaspaceSize=512m -XX:MetaspaceSize=512m -XX:MaxDirectMemorySize=256m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./java_pid<pid>.hprof -Dbasedir=/export/App -Dfile.encoding=UTF-8

2.2 JVM监控图

下图为开启异步日志后的GC和堆内存监控图，在左下角的堆内存图可以明显的看到堆内存的上涨情况，特别是白天业务量大的时候，按此趋势正好3天就能把堆内存涨到90%的告警阈值。

下图为未开启异步记录日志的同步记录日志的监控图，可以看到JVM的堆空间是一个很平直的波动，并不会随时间的增加而上涨。

下图是异步和同步的对比图，红色的是开启了异步记录日志：

排查过程

分析可能出现问题的原因：

1、大日志日志导致的内存溢出；

2、日志打印太多导致的内存溢出；

3、log4j异步日志的隐藏问题/bug。

3.1 方向一：日志打印太多

首先排查上述可能的原因1&2，可以肯定的是跟日志有关，因为这个应用基本没有业务逻辑，也不存在大量的计算，最多的是日志打印，那为什么不减少日志打印或干脆关闭日志打印呢，是的，这个应用平时是关闭日志打印的，最近是为了配合仓做切量才打开的日志打印。

那么问题是由日志多导致的吗，说是，也可以说也不是，不是的原因是因为在开启异步日志之前已开启日志打印一段时间了，没有出现内存溢出的情况，所以推测日志多不是根因，它最多算是诱因。

那关闭能解决吗？直觉告诉我肯定是能解决的，但好奇心驱使我没有去这么做，一是目前没有因为内存溢出出现线上问题；二是还没有出现FGC，JVM的PS收集器是可能承受内存在几乎满的情况下通过FGC来清理内存的，我们可以留一台观察其是否会发生FGC来验证上述的想法；

上图是留的一台机器，在某日的上午近10点果然发生了一次FGC，可以看到左下角的堆内存一下降到不到500M，接着如期继续上涨，说明其不会发生OOM，也不会对线上业务产生影响，可以放心的开启异步日志打印并随时dump堆内存现场下来分析。

这个现象最终并不会发生OOM，所以不能称其为内存溢出或泄漏，只能算作堆内存快速上涨（3天耗尽了4G内存），说明有不停的对象在YGC后被挪到了年老代，最后被FGC掉。

3.2 方向二：大日志

那既不是日志打印多引起的，会是大日志打印引起的吗？下面我们来看dump出的堆内存文件。

通过VisualVM打开dump下来的文件，按照实例数来倒序排，在排除char、byte、int等Java基本类型后，占据第一的是
java.lang.StackTraceElement，对其进行重点排查。

StackTraceElement都是在StackTraceElement[]这个数组对象来，我们打开
java.lang.StackTraceElement[]来看。

可以明显看到java.lang.StackTraceElement[]里的信息是每一个线程所经过的类和方法路径，从线程入口到当前所在类方法一一记录。

此处并没有大日志，也没有日志大的相关信息，此时开始推测会不会是打印的异常日志导致的，因为应用里有一个频繁的业务异常会导致大量的堆栈信息打印，但异步日志开启前后并未有其他变化，而且也找不出可以证实的其他关键信息，只能留下来一个大大的问号【？】。

3.3 方向三：log4j异步日志bug

基本可以排除是日志多和大日志引起的原因后，开始在各大知识库里搜寻公开的log4j异步日志的bug，包括在咨询了搜索引擎和大模型后，并未得到有明确关于log4j的bug相关信息，内心也不相信强大的log4j框架有bug，就算有bug就这么让我遇到了吗，每次抽奖都轮不到的我不可能有这种运气。

继续回头看了很多遍dump出的堆文件，在多次看着char[]占用71%的堆空间情况下，终于忍不住点开了char[]，在看到满屏的日志信息后，顿感眼前一片光明，难道真的是大日志导致的堆内存空间上涨啊。。。

粗略的计算了下，第一大的char[]占据了3M的空间，而且char有474万个实例之多，果然是大日志搞的鬼。

随后进行了更进一步排查，为啥在开启异步日志后会出现这么大量的char[]数组出现呢？

咱们知道JVM是分代进行垃圾回收的，对象实例在一次YGC后如果还存活的话会被放在Survival区，并多次YGC后虚拟机会将还存活的对象实例从Young区挪到Old区。

从前面的堆内存图并结合JVM的分代垃圾回收知识，我们看出在每次YGC后总会有一小部分的对象实例被挪到了年老代里。

那为什么同步日志的时候没有出现这种情况呢，也就是说没有对象实例在多次YGC后还是存活的。

我们开始在log4j异步日志原理和log4j、disruptor的源码里找答案。

关于log4j异步日志原理大家可以在网上搜索相关文章，这里不做冗余介绍了，我们直接从异步日志用到的RingBuffer和RingBufferLogEvent里开始查找相关信息。

在org.apache.logging.log4j.core.async.RingBufferLogEvent#clear方法里我们看到对messageText（存储要打印的日志内容）进行了trim操作，往下追了几层，在java.util.Arrays#copyOf(char[], int)里进行了new char操作，也就是对于超过org.apache.logging.log4j.core.util.Constants#MAX_REUSABLE_MESSAGE_SIZE的日志内容进行了截断，而截断是通过底层java.util.Arrays#copyOf(char[], int)一个字符数组来实现的。

这里有两个前置条件才会进行new char[]操作

首先是
org.apache.logging.log4j.core.util.Constants#ENABLE_THREADLOCALS要为True，我们来看看它的相关源码。

这里因为不是web应用，所以IS_WEB_APP=false，同时也没有配置
log4j2.enable.threadlocals，默认为true。

所以这里
org.apache.logging.log4j.core.util.Constants#ENABLE_THREADLOCALS=ture确认无疑。

我们再来看看
org.apache.logging.log4j.core.util.Constants#MAX_REUSABLE_MESSAGE_SIZE的值。

可以看到如果没有设置
log4j.maxReusableMsgSize的值，MAX_REUSABLE_MESSAGE_SIZE默认值是等于518。

也就是日志大小在大于518个字符的时候是会被截断，而截断是通过Arrays.copyOf的方式new char[]实现的。

我们决定关闭log4j2.enable.threadlocals，将其设置为false来验证是否是messageText被截断导致的堆内存上涨现象。

log4j2.enable.threadlocals=false

上线后第二天的堆内存监控图，可以看出确实没有出现堆内存上涨的情况。

3.4 方向四：无垃圾稳态日志

截止到目前堆内存上涨的问题似乎找到了原因，而且也通过配置threadlocals解决了问题，为什么说似乎呢，后面会有解释，先来看看在前面的排查过程中我们还发现了什么？

红框里的“LOG4J2-1270 no-GC”，这似乎是用户提交的一个issue，难道真的有bug？又一次带着大大的问号【？】去log4j的官网进行了搜索，https://issues.apache.org/jira/browse/LOG4J2-1270，这是有关“LOG4J2-1270”的issue，但并没有发现有用的信息。

倒是红框里最后的“no-GC”是log4j异步日志的一个特性，详细的可以访问log4j日志的官网查看，地址是
https://logging.apache.org/log4j/2.x/manual/garbagefree.html。

《Garbage-free Steady State Logging》确实和前面看到的源码相符，在
ENABLE_THREADLOCALS=ture的情况下除了会重用RingBufferLogEvent等外，RingBufferLogEvent里的messageText和parameters也是会被重用的，不然就会被messageText = null;和parameters = null;。

但是这里说的是“no-GC”，而现在的现象是出现了Garbage，并且是用FGC的，源码422行的备注。

// ensure that excessively long char[] arrays are not kept in memory forever

翻译过来也是说的“确保过长的char[]数组不会永远保存在内存中”，似乎是哪里对不上了？

我们回到messageText上来，仔细想想异步日志虽然是重用RingBufferLogEvent，但每次在日志输出给磁盘IO后如果日志长度大于518个字符是要被new出来的char[]替掉的，也就是日志内容大于518个字符的char[]数组是活不过多次YGC的，是不可能进入到年老代的。

似乎和我们的《Garbage-free Steady State Logging》是对应的，请允许我再一次用似乎这个词，因为和现象确实是朝着两个方向走。

我们决定写一个本地测试类，来验证StringBuilders.trimToMaxSize在截断字符数组后是否会在多次GC后依然存活于堆内存中。

以下是测试类的代码，首先创建一个512长度的StringBuilder，通过循环append放入32个A和480个B，sleep30秒用来操作dump堆内存文件，再将messageText进行截断，再次操作dump，分别分析两次dump出的文件，观察char[]数组的内容。

public static void main(String[] args) throws InterruptedException {    StringBuilder messageText = new StringBuilder(512);
    for (int i = 0; i < 32; i++) {        messageText.append('A');    }    for (int i = 0; i < 480; i++) {        messageText.append('B');    }
    Thread.sleep(1000 * 30);
    StringBuilders.trimToMaxSize(messageText, 256);
    Thread.sleep(1000 * 1000);}

JVM启动参数

-XX:InitialHeapSize=20M-XX:MaxHeapSize=20M-XX:MaxNewSize=10M-XX:NewSize=10M-XX:+PrintGC-XX:+PrintGCDetails-XX:+PrintGCTimeStamps-Xloggc:./gc.log

第一次dump出的messageText是1040B。

第二次dump出的messageText是528B，是被截断后new出来的char[]，堆内存中经过一次GC是没有512长度的StringBuilder，说明第一个StringBuilder在GC后被清理掉了。

下面是两次操作的GC日志。

OpenJDK 64-Bit Server VM (25.345-b01) for bsd-amd64 JRE (1.8.0_345-b01), built on Aug  2 2022 11:46:33 by "jenkins" with gcc 4.2.1 Compatible Apple LLVM 10.0.1 (clang-1001.0.46.4)Memory: 4k page, physical 16777216k(12992k free)
/proc/meminfo:
CommandLine flags: -XX:InitialHeapSize=20971520 -XX:MaxHeapSize=20971520 -XX:MaxNewSize=10485760 -XX:NewSize=10485760 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 19.724: [GC (Heap Dump Initiated GC) [PSYoungGen: 8165K->1024K(9216K)] 8973K->2519K(19456K), 0.0091384 secs] [Times: user=0.03 sys=0.01, real=0.01 secs] 19.734: [Full GC (Heap Dump Initiated GC) [PSYoungGen: 1024K->0K(9216K)] [ParOldGen: 1495K->2231K(10240K)] 2519K->2231K(19456K), [Metaspace: 9337K->9337K(1058816K)], 0.0119249 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 92.727: [GC (Heap Dump Initiated GC) [PSYoungGen: 2527K->288K(9216K)] 4758K->2519K(19456K), 0.0059243 secs] [Times: user=0.02 sys=0.01, real=0.01 secs] 92.733: [Full GC (Heap Dump Initiated GC) [PSYoungGen: 288K->0K(9216K)] [ParOldGen: 2231K->1929K(10240K)] 2519K->1929K(19456K), [Metaspace: 9823K->9738K(1058816K)], 0.0215627 secs] [Times: user=0.05 sys=0.01, real=0.02 secs]

通过上面的测试实验证实了Log4j的异步日志确认是no GC的。

难道有别的对象指向了RingBufferLogEvent里的messageText，我们又翻了几遍源码，仍是没有找到有指向messageText的对象，此刻陷入了僵局。

此后我们又回头继续看dump的堆内存文件，在多次打开char[]实例后看到了一个现象，就在大概在6000多个char[]以后有大量的1056B的char[]。

从上面两个图我们可以看到从近7000到221万的地方，大概有200多万的char[]实例都是1056B，难道这是大于518个字符后截断时被new出来的新char[]对象？带着这个疑问重新回到源码来找答案。

既然1056B和518个字符是能对应上，也就是说我们现在的方向是对的，让我们继续往下走走，new出来的char[]再被使用的时候会怎么样呢

如果大于518个字符还是会被替掉，还是会被YGC掉，因为潜意识里一直觉得是大日志导致的，所以一直在考虑大日志也就是肯定是大于518个字符。突然转念一想，大于518个字符，如果小于呢，小于等于518个字符会怎么样。

如果小于等于518个字符的话......，也就是会重用这个new出来的char[]，这样在多次YGC后这个实例就会从Eden区到Survival区再到Old区，如果这个时候来一个大于518个字符的日志呢，O(∩_∩)O哈哈~

画面感来了，那个518字符的char[]被遗弃在了Old区，Young区里多了一个大于518个字符的新char[]实例。

为了证实上面的推测我们从
java.lang.AbstractStringBuilder#append(java.lang.CharSequence)来找答案。

可以看到在append的时候如果char[]的长度不够的话是会进行扩容的，而扩容也是通过java.util.Arrays#copyOf(char[], int)，也就是new char[]。

到这问题基本就已经很清晰了，原因就是我们的日志打印从小日志到大日志都有，不等长，日志内容是各业务系统在生产过程中的上下文信息，有长有短。

RingBufferLogEvent里的messageText在来来回回的重用过程中，经过多次YGC就一定会有机会将518个字符长度的char[]遗弃在了Old区，长时间积累就导致了JVM堆空间不断上涨，最后经过一次FGC就能清除掉所有的char[]垃圾对象。

JVM堆内存示意图，在多次GC后char[518]对象被挪到了old区，在某一次遇到大于518个字符日志的时候，在eden区new了一个新的char[]数组，原来的char[518]被留在了old区变成了垃圾对象。

解决方案

4.1 设置log4j2.enable.threadlocals

log4j2.enable.threadlocals=false

通过在log4j2.component.properties文件里设置log4j2.enable.threadlocals=false可以关闭log4j的threadlocals从而使log4j的Garbage-free失效。每次都将messageText=null，这样就能在YGC的时候清理掉日志字符实例。

4.2 设置log4j.maxReusableMsgSize

log4j.maxReusableMsgSize=一个比较长的字符长度

如果可以确定日志大小或者是日志最大的长度，可以根据日志长度设置log4j.maxReusableMsgSize一个合理的值，使其不会出现字符数组频繁的trim和ensureCapacity，从而避免在Young区new char[]数组。

4.3 控制日志输出长度

这个其实是最好的方案，因为日志本来就不应该输出长日志内容，无论是从性能、存储、查看和排查，大日志输出打印都不是一个好的设计。

所以在日志打印的地方控制日志长度，比如截取固定的日志长度，或者是计算下所要打印的日志长度，如果大于一定值，只打印日志长度而不打印日志内容。

写在最后

5.1 Garbage-free特性

由于篇幅及时间问题，我们没有做本地的压测对比，暂借用官网的一个压测结果，可以看到log4j的Garbage-free特性还是对应用的性能还是有很大的提升，所以不建议用上面的解决方案1来放弃使用异步日志的Garbage-free特性。

https://logging.apache.org/log4j/2.x/manual/garbagefree.html#async-loggers

5.2 关于ringBufferSize

在排查RingBuffer的过程中发现在dump出的堆空间文件里
org.apache.logging.log4j.core.async.RingBufferLogEvent的实例数是4096，并不是官网所说的256 * 1024个RingBufferLogEvent

带着这个疑问重新查了下log4j的源码，在org.apache.logging.log4j.core.async.DisruptorUtil#calculateRingBufferSize中发现了端倪。

在Constants.ENABLE_THREADLOCALS=true的情况下，ringBufferSize是等于
RINGBUFFER_NO_GC_DEFAULT_SIZE = 4 * 1024，正好等于4096。

Log4j异步日志官网地址：

https://logging.apache.org/log4j/2.x/manual/async.html

5.3 最后选择的解决方案

我们最后选择的是方案3，通过打印日志内容长度，同时对日志进行了截断，只打印前256个字符。

实际的日志打印内容，日志内容是被截断的。

2024-04-17 19:36:43.321-3445306.59406.17133538031451831-jdos_jdl-oms-outbound-worker INFO -[JSF-BZ-22000-12-T-3] com.jd.eclp.jimkv.rpc.EclpJimKVClientAdapter.getByKey(EclpJimKVClientAdapter.java:28) -key=jfs/kveclp/0/1713342604406/2698/12aa38e8324fa5817d0b6bc2065b9555,result.length=267,result={"customerPrintInfo":"{\"orderExtendInfo\":{\"huashengSignJfs\":\"1\",\"huashengIdcardJfs\":\"************132914\",\"huashengSignStandardJfs\":\"\"}}","extendPrintInfo":"{\"CNTemplate\":\"0\",\"thirdPayment\":\"null\",\"receiveMode\":\"null\",\"sendMode\":