记一次疑似JVM内存泄漏的排查过程
# 所有Logger异步配置
log4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
# 日志队列满的处理策略,丢弃
log4j2.asyncQueueFullPolicy=Discard
# 丢弃日志的级别
log4j2.discardThreshold=ERROR
现象
2.1 容器和JVM配置
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.1 方向一:日志打印太多
那关闭能解决吗?直觉告诉我肯定是能解决的,但好奇心驱使我没有去这么做,一是目前没有因为内存溢出出现线上问题;二是还没有出现FGC,JVM的PS收集器是可能承受内存在几乎满的情况下通过FGC来清理内存的,我们可以留一台观察其是否会发生FGC来验证上述的想法;
3.2 方向二:大日志
那既不是日志打印多引起的,会是大日志打印引起的吗?下面我们来看dump出的堆内存文件。
java.lang.StackTraceElement,对其进行重点排查。
StackTraceElement都是在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区。
在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,我们来看看它的相关源码。
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。
我们决定关闭log4j2.enable.threadlocals,将其设置为false来验证是否是messageText被截断导致的堆内存上涨现象。
log4j2.enable.threadlocals=false
3.4 方向四:无垃圾稳态日志
截止到目前堆内存上涨的问题似乎找到了原因,而且也通过配置threadlocals解决了问题,为什么说似乎呢,后面会有解释,先来看看在前面的排查过程中我们还发现了什么?
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;。
// ensure that excessively long char[] arrays are not kept in memory forever
翻译过来也是说的“确保过长的char[]数组不会永远保存在内存中”,似乎是哪里对不上了?
以下是测试类的代码,首先创建一个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);
}
-XX:InitialHeapSize=20M
-XX:MaxHeapSize=20M
-XX:MaxNewSize=10M
-XX:NewSize=10M
-XX:+PrintGC
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-Xloggc:./gc.log
下面是两次操作的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的。
此后我们又回头继续看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)来找答案。
JVM堆内存示意图,在多次GC后char[518]对象被挪到了old区,在某一次遇到大于518个字符日志的时候,在eden区new了一个新的char[]数组,原来的char[518]被留在了old区变成了垃圾对象。
解决方案
4.1 设置log4j2.enable.threadlocals
log4j2.enable.threadlocals=false
4.2 设置log4j.maxReusableMsgSize
log4j.maxReusableMsgSize=一个比较长的字符长度
4.3 控制日志输出长度
这个其实是最好的方案,因为日志本来就不应该输出长日志内容,无论是从性能、存储、查看和排查,大日志输出打印都不是一个好的设计。
所以在日志打印的地方控制日志长度,比如截取固定的日志长度,或者是计算下所要打印的日志长度,如果大于一定值,只打印日志长度而不打印日志内容。
写在最后
5.1 Garbage-free特性
由于篇幅及时间问题,我们没有做本地的压测对比,暂借用官网的一个压测结果,可以看到log4j的Garbage-free特性还是对应用的性能还是有很大的提升,所以不建议用上面的解决方案1来放弃使用异步日志的Garbage-free特性。
5.2 关于ringBufferSize
在排查RingBuffer的过程中发现在dump出的堆空间文件里
org.apache.logging.log4j.core.async.RingBufferLogEvent的实例数是4096,并不是官网所说的256 * 1024个RingBufferLogEvent
RINGBUFFER_NO_GC_DEFAULT_SIZE = 4 * 1024,正好等于4096。
Log4j异步日志官网地址:
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\":
5.4 留一个小问题
private StringBuilder messageText;
org.apache.logging.log4j.core.async.RingBufferLogEvent#messageText被截断后的长度是518个字符,为什么在JVM里占用的内存空间是1056Byte?
欢迎大家在评论区交流。
参考资料
Log4j async -
https://logging.apache.org/log4j/2.x/manual/async.html
LOG4J2-1270:
https://issues.apache.org/jira/browse/LOG4J2-1270
Log4j无垃圾稳态记录 -
https://logging.apache.org/log4j/2.x/manual/garbagefree.html
Log4j无垃圾稳态记录(中文版) -
https://www.docs4dev.com/docs/zh/log4j2/2.x/all/manual-garbagefree.html
微信扫码关注该文公众号作者