4. RingBuffer 满了 log4j2 会发生什么？
当 RingBuffer 满了，如果在 log4j2.component.properties 配置了 AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull=false，则会 Wait（其实是 park） 在 Disruptor 的 produce 方法上，等待消费出下一个可以生产的环形 buffer 槽；默认这个配置为 true，即所有生产日志的线程尝试获取全局中的同一个锁(private final Object queueFullEnqueueLock = new Object();)：
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); } }
默认配置的时候，异常堆栈和我们 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) 省略业务方法堆栈
配置为 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)
5. 为何会满，我们的消费线程当时在干啥？
我们来看下当时的消费线程是否有异常，由于当时硬盘 io 看系统监控并没有异常，所以这个线程很大可能是 Runnable 的，不断的在写入日志。同时，我们知道，写入文件 java 底层基于 native 调用，所以我们查看 JFR 的 native 方法采集。使用事件查看器中的 Method Profiling Sample Native，右键点击，并选择“使用所选类型事件创建新页”：
在创建出来的新页中，按照线程分组查看，查看 Log4j2 的 disruptor 消费线程，可以得出下图：
可以看出：在出问题的时间段，采集到的写入日志文件的事件数量明显增多很多，并且，通过堆栈可以看到：
"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)
log4j2 调用了很多次 flush， JFR 显示采集到的事件，每次都调用了 flush。每次调用 flush，都会造成文件真正写的 native 调用。而消费慢的原因，其实就是这种 native 调用太多，系统写入不过来了。
问题解决
我们可以通过以下四个方向解决这个问题：
- 减少日志输出，精简日志，这是比较基础的方式，也是比较简单的方式，但是身为一个技术人，我们不能满足于此
- 增加硬盘 io，这个也是比较基础简单的解决方式
- 我们是否可以减少这个 flush 呢？答案是可以的，我们可以配置 Appender 的
immediateFlush为 false。 - 增加监控，针对堆栈包含
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>
这里的原理对应源码：
AbstractOutputStreamAppender.java
protected void directEncodeEvent(final LogEvent event) { getLayout().encode(event, manager); //如果配置了 immdiateFlush （默认为 true）或者当前事件是 EndOfBatch if (this.immediateFlush || event.isEndOfBatch()) { manager.flush(); } }
那么对于 Log4j2 Disruptor 异步日志来说，什么时候 LogEvent 是 EndOfBatch 呢？是在消费到的 index 等于生产发布到的最大 index 的时候，这也是比较符合性能设计考虑，即在没有消费完的时候，尽可能地不 flush，消费完当前所有的时候再去 flush：
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++; } } }
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(); }
