log4j日志打印导致OOM问题

YoohuDeLi

已于 2024-06-14 15:16:06 修改

阅读量1.2k

点赞数 11

于 2024-06-10 19:10:37 首次发布

本文链接：https://blog.csdn.net/u014800975/article/details/139580576

版权

JVM 专栏收录该内容

2 篇文章 0 订阅

订阅专栏

一、背景

某天压测，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("日志打印限流中……");
    }
}