log4j日志打印导致OOM问题

一、背景

某天压测，QPS压到一定值后机器就开始重启，出现OOM，好在线上机器配置了启动参数-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/**/**heapdump.hprof。将dump文件下载到本地，打开Java sdk bin目录下的jvisualvm工具，导入dump文件，发现有非常多的char[]对象，于是开始分析原因。

二、问题定位

点击工具栏概要，找到发生OutOfMemoryError的线程堆栈，发现报错跟log4j相关。点击工具栏实例数，靠前的对象也基本跟日志打印有关。

定位到具体的代码行，RequestLogAspect.java:194（对应下面代码倒数第二行），部分代码如下：

// aop 执行后的日志
StringBuilder afterReqLog = new StringBuilder(200);
// 日志参数
List<Object> afterReqArgs = new ArrayList<>();
afterReqLog.append("\n\n================  Response Start  ================\n");
try {
    Object result = point.proceed();
    // 打印返回结构体
    afterReqLog.append("===Result===  {}\n");
    afterReqArgs.add(toJson(result));
    return result;
} finally {
    long tookMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs);
    afterReqLog.append("<=== {}: {} ({} ms)\n");
    afterReqArgs.add(requestMethod);
    afterReqArgs.add(requestURI);
    afterReqArgs.add(tookMs);
    afterReqLog.append("================  Response End   ================\n");
    log.info(afterReqLog.toString(), afterReqArgs.toArray());
}

三、问题分析

上面这段代码的目的是打印出参，当出参result对象非常大时，高并发情况下，会占用比较多的堆内存。而且这段日志打印的代码，将result转为Json串保存在afterReqArgs里，最后通过log.info输出，而log.info又通过StringBuilder将字符串拼接输出，导致堆内存中有非常多的大字符串对象，最终导致OOM。见log4j源码org.apache.logging.log4j.message.ParameterizedMessage#getFormattedMessage。

四、问题复现

本机配置：Apple M1芯片，内存16G。设置JVM启动参数-Xmx256m -Xms256m，Jmeter配置如下图。执行后稳定复现OOM。

五、解决方案

1、不打印大对象

由于这个压测接口查询的内容就是会很大，所以最简单的方式就是不打印这个大对象出参。通过excludeFullLogPatterns配置哪些接口不打印result。

try {
    result = point.proceed();
    return result;
} finally {
    if (requestLogProperties.getResponseLogEnable() && !isExcludeResponseLog(requestURI)) {
        printLogDiv(requestMethod, requestURI, result, startNs);
    }
}

/**
 * 分情况打印日志
 */
private void printLogDiv(String requestMethod, String requestURI, Object result, long startNs) {
    if (isExcludeFullResponseLog(requestURI)) {
        long tookMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs);
        log.info("Response log method[{}], path[{}], tookMs[{}]", requestMethod, requestURI, tookMs);
    } else {
        printFullLog(requestMethod, requestURI, result, startNs);
    }
}
/**
 * 打印日志-全量
 */
private void printFullLog(String requestMethod, String requestURI, Object result, long startNs) {
    long tookMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs);
    if (result == null) {
        log.info("Response log method[{}], path[{}], tookMs[{}]", requestMethod, requestURI, tookMs);
    } else {
        log.info("Response log method[{}], path[{}], tookMs[{}], result[{}]", requestMethod, requestURI, tookMs,
                toFastJson(result));
    }
}
/**
 * 是否排除全量出参日志
 */
private final AntPathMatcher antPathMatcher = new AntPathMatcher();
private boolean isExcludeFullResponseLog(String path) {
    if (CollectionUtils.isEmpty(requestLogProperties.getExcludeFullLogPatterns())) {
        return false;
    }
    return requestLogProperties.getExcludeFullLogPatterns()
            .stream()
            .anyMatch(pattern -> antPathMatcher.match(pattern, path));
}
@Data
@Component
public class RequestLogProperties {

    /**
     * 开启出参打印日志
     */
    @Value("${gaotu.request.log.responseEnable:true}")
    private Boolean responseLogEnable;

    /**
     * 不打印完整日志的url
     */
    @Value("#{'${gaotu.request.log.excludeFullLogPatterns:/query/question-list}'?.split(',')}")
    private List<String> excludeFullLogPatterns;

    /**
     * 不打印出参日志的url
     */
    @Value("#{'${gaotu.request.log.excludeResponseLogPatterns:}'?.split(',')}")
    private List<String> excludeResponseLogPatterns;
}

2、修改log4j配置

设置log4j对应ringBuffer的大小和ringBuffer满时日志的丢弃策略。工具栏实例数显示，ringBuffer中entry对象也非常多。可以参考https://blog.csdn.net/ryo1060732496/article/details/135966098。


ringBuffer设置的源码在org.apache.logging.log4j.core.async.DisruptorUtil#calculateRingBufferSize：

拒绝策略的源码在org.apache.logging.log4j.core.async.AsyncQueueFullPolicyFactory#create：

具体修改方式为：
方法一：通过JVM启动参数配置：-Dlog4j2.asyncLoggerConfigRingBufferSize=512 -DLog4jAsyncQueueFullPolicy=Discard。
在设置-Xmx256m -Xms256m情况下，RingBufferSize设置为1024时会OOM，ringBuffer具体配置看压测而定。
方法二：通过log4j2.component.properties配置：

AsyncLoggerConfig.RingBufferSize=512
log4j2.AsyncQueueFullPolicy=Discard
log4j2.DiscardThreshold=INFO

配置文件读取源码在org.apache.logging.log4j.util.PropertiesUtil：

3、限流

通过限流的方式来打印日志，当超过限流值时不打印出参日志。（本文限流用的RateLimiter）

Object result = null;
try {
    result = point.proceed();
    return result;
} finally {
    if (requestLogProperties.getResponseLogEnable() && !isExcludeResponseLog(requestURI)) {
        printLogLimiter(requestMethod, requestURI, result, startNs);
    }
}

/**
 * 限流的方式
 */
private static Double questionLimit = 20D; //具体设置多少看压测
private static DynamicRateLimiter questionLimiter = DynamicSuppliers
        .dynamicRateLimiter(() -> questionLimit);
private void printLogLimiter(String requestMethod, String requestURI, Object result, long startNs) {
    if (questionLimiter.tryAcquire()) {
        printFullLog(requestMethod, requestURI, result, startNs);
    } else {
        log.info("日志打印限流中……");
    }
}

4、其他

考虑过日志截断，但是截断仍然需要将对象转为Json串再截取，对性能和内存仍然有影响，依然会OOM。

参考资料：

《Log4j2-29-log4j2 discard policy 极端情况下的丢弃策略 同步+异步配置的例子》https://blog.csdn.net/ryo1060732496/article/details/135966098
《Log4j2异步情况下怎么防止丢日志的源码分析以及队列等待和拒绝策略分析》https://www.cnblogs.com/yangfeiORfeiyang/p/9783864.html
《log4j2异步详解及高并发下的优化》https://blog.csdn.net/qq_35754073/article/details/104116487
《Disruptor详解》：https://www.jianshu.com/p/bad7b4b44e48
《从阿里来个技术大佬，入职就给我们分享Java打日志的几大神坑！》https://blog.csdn.net/qq_42046105/article/details/127626058
《Java日志通关（四） - Logback 介绍》https://mp.weixin.qq.com/s/UR30lfp_Guu9d6f0jzWfJw
《Java日志通关（五） - 最佳实践》https://mp.weixin.qq.com/s/KrJ1s1bCjOQLlnWeUaHJvg