一次鞭辟入里的 Log4j2 异步日志输出阻塞问题的定位 (2)

image

简单来说,多线程通过 log4j2 的门面类 org.apache.logging.log4j.Logger 进行日志输出,被封装成为一个 org.apache.logging.log4j.core.LogEvent,放入到 Disruptor 的环形 buffer 中。在消费端有一个单线程消费这些 LogEvent 写入对应的 Appender,我们这里只有一个 Appender,其配置是:

<RollingFile append="true" filePattern="./app.log-%d{yyyy.MM.dd.HH}"> <PatternLayout pattern="${logFormat}"/> <Policies> <TimeBasedTriggeringPolicy interval="1" modulate="true"/> </Policies> <DirectWriteRolloverStrategy maxFiles="72"/> </RollingFile>

异步日志 logger 配置为(配置 includeLocation 为 false,避免每次打印日志需要获取调用堆栈的性能损耗):

<Asyncroot level="info" includeLocation="false"> <appender-ref ref="file"/> </Asyncroot>

log4j component 额外配置为:

log4j2.component.properties:

# 当没有日志的时候,消费线程通过 Block 等待日志事件到来,这样 CPU 占用最少 AsyncLoggerConfig.WaitStrategy=Block 3. log4j2 disruptor 的 RingBuffer 的大小

既然是一个环形 Buffer,它的容量是有限的,我们这里没有修改它的大小,走的是默认配置,查看其源码:

AsyncLoggerConfigDisruptor.java

public synchronized void start() { //省略其他代码 ringBufferSize = DisruptorUtil.calculateRingBufferSize("AsyncLoggerConfig.RingBufferSize"); disruptor = new Disruptor<>(factory, ringBufferSize, threadFactory, ProducerType.MULTI, waitStrategy); }

DisruptorUtil.java

private static final int RINGBUFFER_MIN_SIZE = 128; private static final int RINGBUFFER_DEFAULT_SIZE = 256 * 1024; private static final int RINGBUFFER_NO_GC_DEFAULT_SIZE = 4 * 1024; static int calculateRingBufferSize(final String propertyName) { //是否启用了 ThreadLocal,如果是则为 4 kB,不是则为 256 kB int ringBufferSize = Constants.ENABLE_THREADLOCALS ? RINGBUFFER_NO_GC_DEFAULT_SIZE : RINGBUFFER_DEFAULT_SIZE; //读取系统变量,以及 log4j2.component.properties 文件获取 propertyName(这里是 AsyncLoggerConfig.RingBufferSize) 这个配置 final String userPreferredRBSize = PropertiesUtil.getProperties().getStringProperty(propertyName, String.valueOf(ringBufferSize)); try { int size = Integer.parseInt(userPreferredRBSize); //如果小于 128 字节则按照 128 字节设置 if (size < RINGBUFFER_MIN_SIZE) { size = RINGBUFFER_MIN_SIZE; LOGGER.warn("Invalid RingBufferSize {}, using minimum size {}.", userPreferredRBSize, RINGBUFFER_MIN_SIZE); } ringBufferSize = size; } catch (final Exception ex) { LOGGER.warn("Invalid RingBufferSize {}, using default size {}.", userPreferredRBSize, ringBufferSize); } //取最近的 2 的 n 次方,因为对于 2 的 n 次方取余等于对于 2^n-1 取与运算,这样更快 return Integers.ceilingNextPowerOfTwo(ringBufferSize); }

如果启用了 ThreadLocal 这种方式生成 LogEvent,每次不新生成的 LogEvent 用之前的,用 ThreadLocal 存储的,这样避免了创建新的 LogEvent。但是考虑下面这种情况:

logger.info("{}", someObj);

这样会造成强引用,导致如果线程没有新的日志,这个 someObj 一直不能回收。所以针对 Web 应用,log4j2 默认是不启用 ThreadLocal 的 方式生成 LogEvent

Constants.java

public static final boolean IS_WEB_APP = PropertiesUtil.getProperties().getBooleanProperty( "log4j2.is.webapp", isClassAvailable("javax.servlet.Servlet")); public static final boolean ENABLE_THREADLOCALS = !IS_WEB_APP && PropertiesUtil.getProperties().getBooleanProperty( "log4j2.enable.threadlocals", true);

由此,可以看出,我们的 RingBuffer 的大小为 256 kB

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); } }

内容版权声明:除非注明,否则皆为本站原创文章。

转载注明出处:https://www.heiqu.com/zwwfdw.html