log4j日志导致OOM案例_vlambda技术博客

vlambda
2021-08-16

log4j日志导致OOM案例

背景：sofaboot服务端，时不时收到JVM GC告警提示。

相关设置：垃圾回收器采用g1。log4j-api 2.8.2 版本。

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath

当发生OOM时候，会自动将内存信息保存到指定目录，方便使用MAT等工具进行分析。

结论：代码里有频繁的日志打印，并且会打印大对象，单条日志较大，导致jvm被大量日志对象占用，从而导致oom问题。

解决方法：对log4j进行版本升级、或者减少不必要的超大对象打印。

分析过程具体如下。

一、log4j 2.8.2版本中存在的问题及后续版本的修复

log4j-api 2.8.2 版本，org.apache.logging.log4j.message.ParameterizedMessage

@Overridepublic String getFormattedMessage() { if (formattedMessage == null) { final StringBuilder buffer = getThreadLocalStringBuilder(); formatTo(buffer); formattedMessage = buffer.toString(); } return formattedMessage;}
private static StringBuilder getThreadLocalStringBuilder() { StringBuilder buffer = threadLocalStringBuilder.get(); if (buffer == null) { buffer = new StringBuilder(DEFAULT_STRING_BUILDER_SIZE); threadLocalStringBuilder.set(buffer); } buffer.setLength(0); return buffer;}

在使用 log.info(“test ->, {}”, body)代码时，log4j2会走到getFormattedMessage方法，由于低于2.9.0版本的只会将length设置为0，对于stringbuilder只是字符个数变为了0，实际上其持有的字符还是在内存中，具体可以参考它的capacity方法，StringBuilder容量并没有改变。

https://issues.apache.org/jira/browse/LOG4J2-1858 2.9版本中，fix了此问题

log4j 2.9.0版本 org.apache.logging.log4j.message.ParameterizedMessage

 /** * Returns the formatted message. * @return the formatted message. */@Overridepublic String getFormattedMessage() { if (formattedMessage == null) { final StringBuilder buffer = getThreadLocalStringBuilder(); formatTo(buffer); formattedMessage = buffer.toString(); StringBuilders.trimToMaxSize(buffer, Constants.MAX_REUSABLE_MESSAGE_SIZE); } return formattedMessage;}
private static StringBuilder getThreadLocalStringBuilder() { StringBuilder buffer = threadLocalStringBuilder.get(); if (buffer == null) { buffer = new StringBuilder(DEFAULT_STRING_BUILDER_SIZE); threadLocalStringBuilder.set(buffer); } buffer.setLength(0); return buffer;}

org.apache.logging.log4j.util.StringBuilders

/** * Ensures that the char[] array of the specified StringBuilder does not exceed the specified number of characters. * This method is useful to ensure that excessively long char[] arrays are not kept in memory forever. * * @param stringBuilder the StringBuilder to check * @param maxSize the maximum number of characters the StringBuilder is allowed to have * @since 2.9 */public static void trimToMaxSize(final StringBuilder stringBuilder, final int maxSize) { if (stringBuilder != null && stringBuilder.capacity() > maxSize) { stringBuilder.setLength(maxSize); stringBuilder.trimToSize(); }}

在2.9.0版本修复了此问题，stringbuilder会被裁剪容量，最大容量被设置为(128 * 2 + 2) * 2 + 2，通过裁剪避免日志占用大量内存导致oom的问题。
当buffer的长度大于某一值时会触发stringBuilder的trimToSize操作，这个方法会回收StringBuilder的缓存。
因此只要更新log4j2的版本即可解决这个内存泄漏的问题。

public static final int MAX_REUSABLE_MESSAGE_SIZE = size("log4j.maxReusableMsgSize", (128 * 2 + 2) * 2 + 2);
private static int size(final String property, final int defaultValue) { return PropertiesUtil.getProperties().getIntegerProperty(property, defaultValue);}

2.9.0之后可以通过设置log4j.maxReusableMsgSize调整最大容量。

二、有关打印的线程

log4j的bug，导致StringBuilder里字段串对象很大。但是我们服务端的线程数量不是无限的。对于spring boot + tomcat，springboot官方默认的配置如下：

以上默认值，在实际工程中，可依据服务器配置等，做一些修改，压测时候：

获取tomcat进程pid ：ps -ef|grep tomcat

统计该tomcat进程内的线程个数：ps -Lf 29295 |wc -l

对于springboot + jetty的情况，也有类似的默认配置值，如server.jetty.threads.max，具体可见：https://docs.spring.io/spring-boot/docs/current/reference/htmlsingle/#application-properties。

对于sofaboot应用，sofa-rpc-all-5.6.3.jar中rpc-config-default.json也可以看到类似配置：

 // 默认业务线程池最小 "server.pool.core": 20, // 默认业务线程池最大 "server.pool.max": 200,  // 默认业务线程池队列大小 "server.pool.queue": 0,

我们的应用中，设置的默认业务线程池最大值超过了 200，假设是N。

public class BusinessPool {
 public static ThreadPoolExecutor initPool(ServerConfig serverConfig) { int minPoolSize = serverConfig.getCoreThreads(); int maxPoolSize = serverConfig.getMaxThreads(); int queueSize = serverConfig.getQueues(); int aliveTime = serverConfig.getAliveTime();
 BlockingQueue<Runnable> poolQueue = queueSize > 0 ? new LinkedBlockingQueue<Runnable>( queueSize) : new SynchronousQueue<Runnable>();
 return new ThreadPoolExecutor(minPoolSize, maxPoolSize, aliveTime, TimeUnit.MILLISECONDS, poolQueue); }
}

综上，线程数都是固定的数量值。我们的sofaboot应用oom问题与下面的例子很相似，借用下面的实例说明。

https://www.cnblogs.com/lylife/p/9247924.html，这个例子里面是：dubbo线程池配置数量是500，一个最大dubbo线程占用内存12M。dubbo线程不死，所以这个对象一直都在。

log4j日志导致OOM案例

一个dubbo线程是有一个threadlocal对象，threadlocal对象里面引用了一个java StringBuilder对象，该对象有char数组6百多万，占用内存12M。

通过ThreadLocalMap$Entry对象里referent属性找到引用ThreadLocal对象:

log4j日志导致OOM案例

只要有一次日志内容打印很多情况下，会造成StringBuilder里字段串对象很大，而且是不会销毁（除非当前ThreadLocal线程销毁了，前面说了项目配置了dubbo 500个线程，dubbo线程不死，所以这个对象一直都在），打印大日志对象次数多了，基本上造成所有dubbo线程ThreadLocal StringBuilder对象都很大。正如第一幅图看到一样，最终造成OOM。

我们的sofaboot应用中，线程池中的keepAliveTime是固定值，当请求量较大，一直没有空闲线程，将会导致oom。最终定位到是对请求的入参和出参做了完整的打印，所以临时解决方案是：将出参中的超大对象字段，先不打印。

三、有关G1垃圾回收器

当新建对象大小超过Region大小一半时，直接在新的一个或多个连续Region中分配，并标记为H。

默认把堆内存按照2048份均分，最后得到一个合理的大小。也可以通过-XX:G1HeapRegionSize参数指定堆内存中一个Region的大小，大小区间只能是1M、2M、4M、8M、16M和32M，总之是2的幂次方。

https://www.jianshu.com/p/0f1f5adffdc1 博文中提到：G1中提供了三种模式垃圾回收模式，young gc、mixed gc 和 full gc，在不同的条件下被触发。如果对象内存分配速度过快，mixed gc来不及回收，导致老年代被填满，就会触发一次full gc，G1的full gc算法就是单线程执行的serial old gc，会导致异常长时间的暂停时间，需要进行不断的调优，尽可能的避免full gc.

参考文章：

1、https://blog.csdn.net/sweatOtt/article/details/115657486

2、https://blog.csdn.net/jslcylcy/article/details/104371137

3、https://blog.csdn.net/zhangdx001/article/details/107768429

4、https://www.jianshu.com/p/0f1f5adffdc1

5、https://www.cnblogs.com/lylife/p/9247924.html