乐趣区

关于java:Log4j2基于Disruptor异步日志优化部分源码学习

jiezi

一、前言

  最近遇到了个 log4j2 写日志导致线程阻塞的问题（多亏了开发小哥日志打的多，不然就没有上面这一系列骚操作）。

大抵形容下过后的状况（内网限度，没法把现场货色拿进去，只能口述了）：

log4j2 配置状况： 同时配置了 3 个 RollingRandomAccessFile，别离针对 SQL 语句、INFO 日志、ERROR 日志，大抵的配置如下：

<RollingRandomAccessFile name="RandomAccessFile" fileName="${FILE_PATH}/async-log4j2.log" append="false"
                  filePattern="${FILE_PATH}/rollings/async-testLog4j2-%d{yyyy-MM-dd}_%i.log.gz">
    <PatternLayout>
        <Pattern>${LOG_PATTERN}</Pattern>
    </PatternLayout>
    <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
    <Policies>
        <TimeBasedTriggeringPolicy interval="1" modulate="true" />
        <SizeBasedTriggeringPolicy size="450MB"/>
    </Policies>
    <DefaultRolloverStrategy max="15" compressionLevel="0"/>
</RollingRandomAccessFile>

问题形容： 1、32C 的机器压缩日志占用 30%+ 的资源；2、tomcat 主线程全副 50%+ 都是 park 状态，线程状态大抵如下；

过后针对 log4j2 给的优化倡议是： 1、配置immediateFlush=false 2、将 filePattern 对应的 gz 后缀去掉（因为对应的compressionLevel=0, 基本不压缩），是否就不会调用 JDK 的 Deflater 进行压缩。【猜想，也是前面还原现场的起因之一，想亲自验证一下】

二、本地复现 & 局部源码学习

  问题复现的过程也是蛮艰苦的，遇到各种问题。上面记录的是我本地复现时遇到的问题以及解决办法，附带一些 log4j2 基于 disruptor 的局部源码学习，篇幅可能会稍长。

环境：Macbook Pro x86（16C32G）、jdk1.8、log4j-core 2.12.1、log4j-api 2.12.1、disruptor 3.4.2

测试代码(启动 50 线程不间断地写日志【现场零碎波及 200 个 Tomcat 线程】)：

public class TestLog4j {private static Logger logger = LogManager.getLogger(TestLog4j.class);
    private final ThreadPoolExecutor executor;

    public TestLog4j() {
        this.executor = new ThreadPoolExecutor(50, 50,
                60, TimeUnit.SECONDS,
                new ArrayBlockingQueue(1000),
                Executors.defaultThreadFactory(),
                new ThreadPoolExecutor.AbortPolicy());
    }

    public void testLog() {for (int i = 0; i < this.executor.getCorePoolSize(); i++) {this.executor.execute(() -> {while (true) {
                    logger.info("测试日志 -- 麻利麻利哄快阻塞 -- 麻利麻利哄快阻塞 -- 麻利麻利哄快阻塞 -- 麻利麻利哄快阻塞" +
                            "-- 麻利麻利哄快阻塞 -- 麻利麻利哄快阻塞 -- 麻利麻利哄快阻塞 -- 麻利麻利哄快阻塞 -- 麻利麻利哄快阻塞" +
                            "-- 麻利麻利哄快阻塞 -- 麻利麻利哄快阻塞 -- 麻利麻利哄快阻塞 -- 麻利麻利哄快阻塞 -- 麻利麻利哄快阻塞");
                }
            });
        }
    }

    public static void main(String[] args) {new TestLog4j().testLog();}
}

局部 log4j2.xml 配置(将备份的压缩日志大小改小至 100M，备份文件数量减少至 100)：

<appenders>
    <RollingRandomAccessFile name="RandomAccessFile" fileName="${FILE_PATH}/async-log4j2.log" append="false"
                      filePattern="${FILE_PATH}/rollings/async-testLog4j2-%d{yyyy-MM-dd}_%i.log.gz">
        <PatternLayout>
            <Pattern>${LOG_PATTERN}</Pattern>
        </PatternLayout>
        <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
        <Policies>
            <TimeBasedTriggeringPolicy interval="1" modulate="true" />
            <SizeBasedTriggeringPolicy size="100MB"/>
        </Policies>
        <DefaultRolloverStrategy max="100" compressionLevel="0"/>
    </RollingRandomAccessFile>
</appenders>
<loggers>
    <!--disruptor 异步日志 -->
    <AsyncLogger name="DisruptorLogger" level="info" includeLocation="false">
        <AppenderRef ref="RandomAccessFile"/>
    </AsyncLogger>
    <Asyncroot level="info" includeLocation="false">
        <appender-ref ref="RandomAccessFile"/>
    </Asyncroot>
</loggers>

（一）线程阻塞 -Blocked

  所有准备就绪，点击运行，jps+jstack+jmap，一片自信满满。关上 thread dump 的那一刻，我就懵了，一片红红的 blocked，此时应上问号脸。线程状况是这样的：

感觉和预期差的有点大啊，看样子是在往 disruptor 的 RingBuffer 里写日志的时候就 blocked 了，能够比照一下之前线程的线程状况，是没有 blocked 的。内存 dump 中如同发现了不一样的：

RingBuffer 只有 4096，印象里没有设置的话默认是 256*1024。

（1）RingBuffer 大小

  org.apache.logging.log4j.core.async包下的 DisruptorUtil 类里定义了很多 Disruptor 相干的配置属性。
其中有三个 RingBuffer size 的动态属性，还有一个获取 RingBufferSize 的办法calculateRingBufferSize。

// DisruptorUtil 类
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) {
    // 如果 ENABLE_THREADLOCALS 为 true，则应用 RINGBUFFER_NO_GC_DEFAULT_SIZE 即 4096 大小的 size
    int ringBufferSize = Constants.ENABLE_THREADLOCALS ? RINGBUFFER_NO_GC_DEFAULT_SIZE : RINGBUFFER_DEFAULT_SIZE;
    // 获取配置文件中自定配置大小，如果没有返回下面 ringBufferSize
    final String userPreferredRBSize = PropertiesUtil.getProperties().getStringProperty(propertyName,
            String.valueOf(ringBufferSize));
    try {int size = Integer.parseInt(userPreferredRBSize);
        // 自定义配置大小小于 128，则将 size 从新赋值为 128
        if (size < RINGBUFFER_MIN_SIZE) {
            size = RINGBUFFER_MIN_SIZE;
            LOGGER.warn("Invalid RingBufferSize {}, using minimum size {}.", userPreferredRBSize,
                    RINGBUFFER_MIN_SIZE);
        }
        // 自定义配置大小从新赋值给 ringBufferSize
        ringBufferSize = size;
    } catch (final Exception ex) {LOGGER.warn("Invalid RingBufferSize {}, using default size {}.", userPreferredRBSize, ringBufferSize);
    }
    return Integers.ceilingNextPowerOfTwo(ringBufferSize);
}

而后看下 Constants.ENABLE_THREADLOCALS 就水落石出了：

/**
     * {@code true} if we think we are running in a web container, based on the boolean value of system property
     * "log4j2.is.webapp", or (if this system property is not set) whether the  {@code javax.servlet.Servlet} class
     * is present in the classpath.
     */
    public static final boolean IS_WEB_APP = PropertiesUtil.getProperties().getBooleanProperty("log4j2.is.webapp", isClassAvailable("javax.servlet.Servlet"));

    /**
     * Kill switch for object pooling in ThreadLocals that enables much of the LOG4J2-1270 no-GC behaviour.
     * <p>
     * {@code True} for non-{@link #IS_WEB_APP web apps}, disable by setting system property
     * "log4j2.enable.threadlocals" to "false".
     * </p>
     */
    public static final boolean ENABLE_THREADLOCALS = !IS_WEB_APP && PropertiesUtil.getProperties().getBooleanProperty("log4j2.enable.threadlocals", true);

大抵意思就是，如果利用不是 web 利用【判断是否存在 javax.servlet.Servlet 这个类】，就默认应用 threadlocals 这种模式，即我本地程序的 RingBuffer 就被设置成了 4096。

正文中也提到，能够设置 jvm 运行时参数，不应用 threadlocals 这种模式，能够这么设置：-Dlog4j2.enable.threadlocals=false

  • Garbage-free logging

    • 大部分日志框架，包含 log4j 会在失常日志输入的时候创立长期对象（log event objects, Strings, char arrays, byte arrays…），这会减少 GC 的压力；
    • 从 Log4j2.6 开始，log4j 默认应用 Garbage-free 这种模式。threadlocals 是 Garbage-free 的其中一种实现，在 ThreadLocal 根底上，会重用对象（例如 log event objects）；
    • 然而在 web 利用中，threadlocals 这种模式很容易导致 ThreadLocal 的内存透露，所以在 web 利用中，不会应用 threadlocals 模式；

    • 一些不齐全 Garbage-free 的性能，不依赖 ThreadLocal，会将 log events 对象转换成 text，继而将 text 间接编码成 bytes 存入 可重用的ByteBuffer，而不须要创立零时的 Strings, char arrays and byte arrays 等对象。

      • 上述性能默认开始（log4j2.enableDirectEncoders默认为 true），在多线程环境下，日志性能可能会不太现实，因为在应用共享 buffer 的时候是同步操作。所以思考性能的话，倡议应用异步日志。

    参考：https://logging.apache.org/lo…，Garbage-free Logging

（2）阻塞的外围办法enqueue

  次要的阻塞点 org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor 的enqueue办法

private void enqueue(final LogEvent logEvent, final AsyncLoggerConfig asyncLoggerConfig) {
    // 如果 synchronizeEnqueueWhenQueueFull 为 true，进入阻塞办法
    if (synchronizeEnqueueWhenQueueFull()) {synchronized (queueFullEnqueueLock) {disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig);
        }
    } else {disruptor.getRingBuffer().publishEvent(translator, logEvent, asyncLoggerConfig);
    }
}
private boolean synchronizeEnqueueWhenQueueFull() {
    return DisruptorUtil.ASYNC_CONFIG_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL
            // Background thread must never block
            && backgroundThreadId != Thread.currentThread().getId();
}

DisruptorUtil中对于 SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL 的两个动态属性：

// 默认都是 true
static final boolean ASYNC_LOGGER_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL = PropertiesUtil.getProperties()
        .getBooleanProperty("AsyncLogger.SynchronizeEnqueueWhenQueueFull", true);
static final boolean ASYNC_CONFIG_SYNCHRONIZE_ENQUEUE_WHEN_QUEUE_FULL = PropertiesUtil.getProperties()
        .getBooleanProperty("AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull", true);

从源码能够看到，默认 enqueue 办法就是走阻塞的分支代码。如果要设置成非阻塞的运行形式，须要手动配置参数，办法如下：
新建 log4j2.component.properties 文件，增加如下配置：
【其余可配置参数详见：https://logging.apache.org/lo…】

# 实用 <root> and <logger> 加
# Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector 配置的异步日志
# 作用于 org.apache.logging.log4j.core.async.AsyncLoggerDisruptor
AsyncLogger.SynchronizeEnqueueWhenQueueFull=false
# 实用 <asyncRoot> & <asyncLogger> 配置的异步日志
# 作用于 org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor
AsyncLoggerConfig.SynchronizeEnqueueWhenQueueFull=false

  • note：

    1. 异步日志配置形式不同的话，会应用不同的解决类（AsyncLoggerConfigDisruptor | AsyncLoggerDisruptor），因而配置参数得相匹配；

    2. 将 SynchronizeEnqueueWhenQueueFull 设置成 false，会导致 CPU 使用率飙升，这个应该也是默认为 true 的起因。能够看上面本地试验的后果，差不多是 10 倍的差距。【官网文档中是不倡议设置成 false 的，除非绑定 CPU 核。】

      • true 时的 CPU 应用「159%」：
      • false 时的 CPU 应用「1565%」：

CPU 高的次要起因：
在 enqueue 办法处没有阻塞的状况下，所有的线程都会进入到 MultiProducerSequencer 的next办法。这个办法是获取 RingBuffer 的可写区间的，办法中有个 while 死循环不断的做 CAS 操作。在 LockSupport.parkNanos(1) 处原作者这边也给了疑难：要不要沿用 WaitStrategy 的期待策略。

@Override
public long next(int n)
{if (n < 1)
    {throw new IllegalArgumentException("n must be > 0");
    }
    long current;
    long next;
    do
    {current = cursor.get();
        next = current + n;
        long wrapPoint = next - bufferSize;
        long cachedGatingSequence = gatingSequenceCache.get();
        if (wrapPoint > cachedGatingSequence || cachedGatingSequence > current)
        {long gatingSequence = Util.getMinimumSequence(gatingSequences, current);
            if (wrapPoint > gatingSequence)
            {LockSupport.parkNanos(1); // TODO, should we spin based on the wait strategy?
                continue;
            }
            gatingSequenceCache.set(gatingSequence);
        }
        else if (cursor.compareAndSet(current, next))
        {break;}
    }
    while (true);
    return next;
}

至此，根本还原现场的状况：

（3）异步日志反复配置的问题

  这是集体的好奇之举。当即应用了 Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector，又在 log4j2.xml 中配置了<asyncRoot> 标签，日志对象将会多一次两头传递：
app -> RingBuffer-1 -> thread a -> RingBuffer-2 -> thread b -> disk。
这会带来不必要的性能损耗。

看下这种状况的线程 dump 就了然了：

（二）日志压缩

尝试去掉 gz 后缀名，优化压缩的资源耗费问题。

  • 批改前，CPU 采样状况，在资源占用前列能够显著看到压缩的相干办法：
  • 去掉 gz 后缀和压缩级别参数，曾经找不到压缩相干的办法了：

验证了之前的猜测，RollingFile 其实就是依据文件后缀来判断是否进行压缩的。

（三）生产线程 (IO 线程) 的 WaitStrategy

  即 log4j2.asyncLoggerWaitStrategy | log4j2.asyncLoggerConfigWaitStrategy 这两配置，次要用来配置期待日志事件的 I / O 线程的策略。
官网文档中给出了 4 种策略：Block, Timeout「默认」, Sleep, Yield。
然而源码中其实有 5 种：

// org.apache.logging.log4j.core.async.DisruptorUtil
static WaitStrategy createWaitStrategy(final String propertyName, final long timeoutMillis) {final String strategy = PropertiesUtil.getProperties().getStringProperty(propertyName, "TIMEOUT");
    LOGGER.trace("property {}={}", propertyName, strategy);
    final String strategyUp = strategy.toUpperCase(Locale.ROOT); // TODO Refactor into Strings.toRootUpperCase(String)
    switch (strategyUp) { // TODO Define a DisruptorWaitStrategy enum?
    case "SLEEP":
        return new SleepingWaitStrategy();
    case "YIELD":
        return new YieldingWaitStrategy();
    case "BLOCK":
        return new BlockingWaitStrategy();
    case "BUSYSPIN":
        return new BusySpinWaitStrategy();
    case "TIMEOUT":
        return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS);
    default:
        return new TimeoutBlockingWaitStrategy(timeoutMillis, TimeUnit.MILLISECONDS);
    }
}

多了一个 BusySpinWaitStrategy 策略「JDK9 才真正实用，9 以下就是简略的死循环」

这里不一一介绍，次要是 disruptor 相干的内容「具体内容能够参考这片文章，写的还能够：https://blog.csdn.net/boling_…」，联合 log4j2 说几点：

  • 默认的 TimeoutBlockingWaitStrategy 和BlockingWaitStrategy策略都是基于 ReentrantLock 实现的，因为底层是基于 AQS，在运行过程中会创立 AQS 的 Node 对象，不合乎 Garbage-free 的思维；
  • SLEEP是 Garbage-free 的，且官网文档提到，相较于 BLOCK 实用于资源受限的环境，SLEEP均衡了性能和 CPU 资源两方面因素。

三、总结

  对于 log4j2 的性能优化，总结以下几点「前面有补充会增加到这里」

  1. 配置滚动日志的时候，若不须要压缩日志，filePattern 的文件名不要以 gz 结尾；
  2. 应用 Disruptor 异步日志的时候，不要同时应用 Log4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector 和<asyncRoot>；
  3. 给 RollingRandomAccessFile 配置 immediateFlush="false" 属性，这样让 I / O 线程批量刷盘（这里其实波及到 native 办法调用的性能问题）；
  4. 能够联合资源状况是否要配置 SynchronizeEnqueueWhenQueueFull 为false；
  5. 结合实际状况是否要更改 I / O 线程的WaitStrategy；
  6. 若日志能够抛弃，能够配置抛弃策略，配置 log4j2.asyncQueueFullPolicy=Discard，log4j2.discardThreshold=INFO「默认」，当队列满时，INFO, DEBUG 和TRACE级别的日志会被抛弃；
退出移动版