1. 首页
  2. 文章

一次鞭辟入里的 Log4j2 日志输出阻塞问题的定位（下）

阿里云开发者社区 · · 54 次点击 · · 开始浏览    

4. RingBuffer 满了 log4j2 会发生什么？

当 RingBuffer 满了，如果在 log4j2.component.properties 配置了 AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull=false，则会 Wait（其实是 park） 在 Disruptor 的 produce 方法上，等待消费出下一个可以生产的环形 buffer 槽；默认这个配置为 true，即所有生产日志的线程尝试获取全局中的同一个锁(private final Object queueFullEnqueueLock = new Object();)：

DisruptorUtil.java

static final boolean ASYNC_CONFIG_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL = PropertiesUtil.getProperties()
        .getBooleanProperty("AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull", true);
private boolean synchronizeEnqueueWhenQueueFull() {
    return DisruptorUtil.ASYNC_CONFIG_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL
            // Background thread must never block
            && backgroundThreadId != Thread.currentThread().getId();
}
private final Object queueFullEnqueueLock = new Object();
private void enqueue(final LogEvent logEvent, final AsyncLoggerConfig asyncLoggerConfig) {
    //如果 AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull=true，默认就是 true
    if (synchronizeEnqueueWhenQueueFull()) {
        synchronized (queueFullEnqueueLock) {
            disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig);
        }
    } else {
        //如果 AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull=false
        disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig);
    }
}
AI 代码解读


默认配置的时候，异常堆栈和我们 JFR 中看到的一样，举个例子：

"Thread-0" #27 [13136] prio=5 os_prio=0 cpu=0.00ms elapsed=141.08s tid=0x0000022d6f2fbcc0 nid=0x3350 waiting for monitor entry  [0x000000399bcfe000]
   java.lang.Thread.State: BLOCKED (on object monitor)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueue(AsyncLoggerConfigDisruptor.java:375)
  - waiting to lock <merged>(a java.lang.Object)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueueEvent(AsyncLoggerConfigDisruptor.java:330)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logInBackgroundThread(AsyncLoggerConfig.java:159)
  at org.apache.logging.log4j.core.async.EventRoute$1.logMessage(EventRoute.java:46)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfig.handleQueueFull(AsyncLoggerConfig.java:149)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logToAsyncDelegate(AsyncLoggerConfig.java:136)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:116)
  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:460)
  at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
  at org.apache.logging.log4j.core.Logger.log(Logger.java:162)
  at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2190)
  at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2144)
  at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2127)
  at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2003)
  at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1975)
  at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1312)
  省略业务方法堆栈
AI 代码解读


配置为 false 的时候，堆栈是这个样子的：

"Thread-0" #27 [18152] prio=5 os_prio=0 cpu=0.00ms elapsed=5.68s tid=0x000002c1fa120e00 nid=0x46e8 runnable  [0x000000eda8efe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
  at jdk.internal.misc.Unsafe.park(java.base@17-loom/Native Method)
  at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17-loom/LockSupport.java:410)
  at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
  at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
  at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:524)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueue(AsyncLoggerConfigDisruptor.java:379)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueueEvent(AsyncLoggerConfigDisruptor.java:330)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logInBackgroundThread(AsyncLoggerConfig.java:159)
  at org.apache.logging.log4j.core.async.EventRoute$1.logMessage(EventRoute.java:46)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfig.handleQueueFull(AsyncLoggerConfig.java:149)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logToAsyncDelegate(AsyncLoggerConfig.java:136)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:116)
  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:460)
  at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
  at org.apache.logging.log4j.core.Logger.log(Logger.java:162)
  at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2190)
  at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2144)
  at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2127)
  at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2003)
  at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1975)
  at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1312)
AI 代码解读


5. 为何会满，我们的消费线程当时在干啥？

我们来看下当时的消费线程是否有异常，由于当时硬盘 io 看系统监控并没有异常，所以这个线程很大可能是 Runnable 的，不断的在写入日志。同时，我们知道，写入文件 java 底层基于 native 调用，所以我们查看 JFR 的 native 方法采集。使用事件查看器中的 Method Profiling Sample Native，右键点击，并选择“使用所选类型事件创建新页”：


image.png


在创建出来的新页中，按照线程分组查看，查看 Log4j2 的 disruptor 消费线程，可以得出下图：


image.png


可以看出：在出问题的时间段，采集到的写入日志文件的事件数量明显增多很多，并且，通过堆栈可以看到：

"Log4j2-TF-2-AsyncLoggerConfig-1" #26 [23680] daemon prio=5 os_prio=0 cpu=406.25ms elapsed=2.89s tid=0x0000022d6f3d4080 nid=0x5c80 runnable  [0x000000399bbfe000]
   java.lang.Thread.State: RUNNABLE
  at java.io.FileOutputStream.writeBytes(java.base@17-loom/Native Method)
  at java.io.FileOutputStream.write(java.base@17-loom/FileOutputStream.java:365)
  at org.apache.logging.log4j.core.appender.OutputStreamManager.writeToDestination(OutputStreamManager.java:261)
  - eliminated <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
  at org.apache.logging.log4j.core.appender.FileManager.writeToDestination(FileManager.java:272)
  - eliminated <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
  at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.writeToDestination(RollingFileManager.java:236)
  - eliminated <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
  at org.apache.logging.log4j.core.appender.OutputStreamManager.flushBuffer(OutputStreamManager.java:293)
  - locked <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
  at org.apache.logging.log4j.core.appender.OutputStreamManager.flush(OutputStreamManager.java:302)
  - locked <0x000000070ee0af40> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
  at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.directEncodeEvent(AbstractOutputStreamAppender.java:199)
  at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.tryAppend(AbstractOutputStreamAppender.java:190)
  at org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:181)
  at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:312)
  at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
  at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
  at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:543)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfig.callAppenders(AsyncLoggerConfig.java:127)
  at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:502)
  at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfig.log(AsyncLoggerConfig.java:121)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfig.logToAsyncLoggerConfigsOnCurrentThread(AsyncLoggerConfig.java:169)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:111)
  at org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapperHandler.onEvent(AsyncLoggerConfigDisruptor.java:97)
  at com.lmax.disruptor.BatchEventProcessor.processEvents(BatchEventProcessor.java:168)
  at com.lmax.disruptor.BatchEventProcessor.run(BatchEventProcessor.java:125)
  at java.lang.Thread.run(java.base@17-loom/Thread.java:1521)
AI 代码解读

log4j2 调用了很多次 flush， JFR 显示采集到的事件，每次都调用了 flush。每次调用 flush，都会造成文件真正写的 native 调用。而消费慢的原因，其实就是这种 native 调用太多，系统写入不过来了。


问题解决

我们可以通过以下四个方向解决这个问题：

  1. 减少日志输出，精简日志，这是比较基础的方式，也是比较简单的方式，但是身为一个技术人，我们不能满足于此
  2. 增加硬盘 io，这个也是比较基础简单的解决方式
  3. 我们是否可以减少这个 flush 呢？答案是可以的，我们可以配置 Appender 的immediateFlush为 false。
  4. 增加监控，针对堆栈包含 org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueue 的 java monitor block 事件进行监控，如果发现时间过长或者数量很多的事件则报警或者重建进程


1. 配置 Appender 的 immediateFlush 为 false

我们可以配置 Appender 的 immediateFlush 为 false，例如：

<RollingFile name="file" append="true"
             filePattern="./app.log-%d{yyyy.MM.dd.HH}"
             immediateFlush="false">
    <PatternLayout pattern="${logFormat}"/>
    <Policies>
        <TimeBasedTriggeringPolicy interval="1" modulate="true"/>
    </Policies>
    <DirectWriteRolloverStrategy maxFiles="72"/>
</RollingFile>
AI 代码解读

这里的原理对应源码：

AbstractOutputStreamAppender.java

protected void directEncodeEvent(final LogEvent event) {
    getLayout().encode(event, manager);
    //如果配置了 immdiateFlush （默认为 true）或者当前事件是 EndOfBatch
    if (this.immediateFlush || event.isEndOfBatch()) {
        manager.flush();
    }
}
AI 代码解读

那么对于 Log4j2 Disruptor 异步日志来说，什么时候 LogEvent 是 EndOfBatch 呢？是在消费到的 index 等于生产发布到的最大 index 的时候，这也是比较符合性能设计考虑，即在没有消费完的时候，尽可能地不 flush，消费完当前所有的时候再去 flush：

BatchEventProcessor.java

private void processEvents()
{
    T event = null;
    long nextSequence = sequence.get() + 1L;
    while (true)
    {
        try
        {
            final long availableSequence = sequenceBarrier.waitFor(nextSequence);
            if (batchStartAware != null)
            {
                batchStartAware.onBatchStart(availableSequence - nextSequence + 1);
            }
            while (nextSequence <= availableSequence)
            {
                event = dataProvider.get(nextSequence);
                //这里 nextSequence == availableSequence 就是 EndOfBatch
                eventHandler.onEvent(event, nextSequence, nextSequence == availableSequence);
                nextSequence++;
            }
            sequence.set(availableSequence);
        }
        catch (final TimeoutException e)
        {
            notifyTimeout(sequence.get());
        }
        catch (final AlertException ex)
        {
            if (running.get() != RUNNING)
            {
                break;
            }
        }
        catch (final Throwable ex)
        {
            exceptionHandler.handleEventException(ex, nextSequence, event);
            sequence.set(nextSequence);
            nextSequence++;
        }
    }
}
AI 代码解读


2. 增加基于 JFR 事件监控

这个需要 Java 14 以上的版本
Configuration config = Configuration.getConfiguration("default");
//设置监控的锁 block 时间超过多少就会采集
config.getSettings().put("jdk.JavaMonitorEnter#threshold", "1s");
try (var es = new RecordingStream(config)) {
    es.onEvent("jdk.JavaMonitorEnter", recordedEvent -> {
        //如果堆栈包含我们关注的，则报警
        if (recordedEvent.getStackTrace().getFrames().stream().anyMatch(recordedFrame -> recordedFrame.toString().contains("org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor.enqueue")))  {
            System.out.println("Alarm: " + recordedEvent);
        }
    });
    es.start();
}
AI 代码解读


本文来自：阿里云开发者社区

感谢作者：阿里云开发者社区

查看原文：一次鞭辟入里的 Log4j2 日志输出阻塞问题的定位（下）

54 次点击  
加入收藏 微博
赞
收入我的专栏
上一篇：云备份技术解析：永久增量备份
添加一条新回复 （您需要 登录 后才能回复 没有账号 ？）
  • 请尽量让自己的回复能够对别人有帮助
  • 支持 Markdown 格式, **粗体**、~~删除线~~、`单行代码`
  • 支持 @ 本站用户；支持表情（输入 : 提示），见 Emoji cheat sheet
  • 图片支持拖拽、截图粘贴等方式上传

用户登录

 今日阅读排行

    加载中

 一周阅读排行

    加载中