日志-log4j2基于AsyncLogger的异步日志打印

前言

在日志-log4j2基于AsyncAppender的异步日志打印一文中，分析了Log4j2如何基于AsyncAppender来实现异步日志打印，本篇文章将分析Log4j2如何基于AsyncLogger来实现异步日志打印。

本篇文章会涉及部分Disruptor队列的相关概念，如果不熟悉Disruptor队列，可以先阅读多线程学习-Disruptor队列了解相关概念。

Log4j2版本：2.17.1

正文

首先搭建示例工程。引入依赖如下所示。

<dependencies>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-slf4j-impl</artifactId>
        <version>2.17.1</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-core</artifactId>
        <version>2.17.1</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-api</artifactId>
        <version>2.17.1</version>
    </dependency>

    <dependency>
        <groupId>com.lmax</groupId>
        <artifactId>disruptor</artifactId>
        <version>3.4.0</version>
    </dependency>
</dependencies>

打印日志的测试类如下所示。

public class LearnLog4j2Async {

    private static final Logger logger = LoggerFactory
            .getLogger(LearnLog4j2Async.class);

    public static void main(String[] args) {
        logger.info("{} be happy every day.", "Lee");
    }

}

要使用AysncLogger，需要在Log4j2的配置文件中使用<AsyncLogger>标签配置一个异步Logger，并为这个异步Logger配置非异步Appender。配置如下所示。

<?xml version="1.0" encoding="UTF-8"?>

<Configuration status="INFO">
    <Appenders>
        <!-- 配置两个非异步Appender -->
        <Console name="MyConsole" target="SYSTEM_OUT">
            <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="%msg%n"/>
        </Console>
        <RollingFile name="MyFile" fileName="mylog.log"
                     filePattern="mylog.log.%i">
            <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY" />
            <PatternLayout pattern="%msg%n"/>
            <SizeBasedTriggeringPolicy size="20M"/>
        </RollingFile>
    </Appenders>

    <Loggers>
        <!-- 为根Logger配置非异步Appender -->
        <Root level="INFO">
            <Appender-ref ref="MyConsole"/>
            <Appender-ref ref="MyFile"/>
        </Root>
        <!-- 定义一个异步Logger并为其配置非异步Appender -->
        <AsyncLogger name="com.lee.learn.log4j2.asynclogger.LearnLog4j2Async" level="INFO" additivity="false">
            <appender-ref ref="MyConsole"/>
        </AsyncLogger>
    </Loggers>
</Configuration>

已知Log4j2框架在首次获取Logger时，会初始化LoggerContext，而初始化LoggerContext时有一个步骤就是将Log4j2配置对象XmlConfiguration设置给LoggerContext并启动XmlConfiguration，这里看一下XmlConfiguration的start()方法，如下所示。

public void start() {
    if (getState().equals(State.INITIALIZING)) {
        initialize();
    }
    LOGGER.debug("Starting configuration {}", this);
    this.setStarting();
    if (watchManager.getIntervalSeconds() >= 0) {
        watchManager.start();
    }
    // 判断是否配置了AsyncLogger
    if (hasAsyncLoggers()) {
        // 调用asyncLoggerConfigDisruptor来启动AsyncLogger
        asyncLoggerConfigDisruptor.start();
    }
    final Set<LoggerConfig> alreadyStarted = new HashSet<>();
    for (final LoggerConfig logger : loggerConfigs.values()) {
        logger.start();
        alreadyStarted.add(logger);
    }
    for (final Appender appender : appenders.values()) {
        appender.start();
    }
    if (!alreadyStarted.contains(root)) {
        root.start();
    }
    super.start();
    LOGGER.debug("Started configuration {} OK.", this);
}

在XmlConfiguration的start()方法中，需要关注的就是调用了asyncLoggerConfigDisruptor的start()方法来启动AsyncLogger，asyncLoggerConfigDisruptor是一个AsyncLoggerConfigDisruptor对象，其在首次初始化AsyncLoggerConfig时被创建，如下所示。

protected AsyncLoggerConfig(final String name,
        final List<AppenderRef> appenders, final Filter filter,
        final Level level, final boolean additive,
        final Property[] properties, final Configuration config,
        final boolean includeLocation) {
    super(name, appenders, filter, level, additive, properties, config,
            includeLocation);
    // 在这里调用XmlConfiguration的getAsyncLoggerConfigDelegate()方法来创建AsyncLoggerConfigDisruptor
    delegate = config.getAsyncLoggerConfigDelegate();
    delegate.setLogEventFactory(getLogEventFactory());
}

AsyncLoggerConfigDisruptor的start()方法中主要逻辑就是创建Disruptor高性能队列，实现如下所示。

public synchronized void start() {
    if (disruptor != null) {
        LOGGER.trace("AsyncLoggerConfigDisruptor not starting new disruptor for this configuration, "
                + "using existing object.");
        return;
    }
    LOGGER.trace("AsyncLoggerConfigDisruptor creating new disruptor for this configuration.");
    // 计算Disruptor队列大小，默认是4096
    ringBufferSize = DisruptorUtil.calculateRingBufferSize("AsyncLoggerConfig.RingBufferSize");
    // 创建等待策略，默认是TimeoutBlockingWaitStrategy
    final WaitStrategy waitStrategy = DisruptorUtil.createWaitStrategy("AsyncLoggerConfig.WaitStrategy");
    
    // 创建线程工厂
    final ThreadFactory threadFactory = new Log4jThreadFactory("AsyncLoggerConfig", true, Thread.NORM_PRIORITY) {
        @Override
        public Thread newThread(final Runnable r) {
            final Thread result = super.newThread(r);
            backgroundThreadId = result.getId();
            return result;
        }
    };
    // 创建队列满时的策略类，这里和AsyncAppender里的策略类是一样的
    asyncQueueFullPolicy = AsyncQueueFullPolicyFactory.create();

    translator = mutable ? MUTABLE_TRANSLATOR : TRANSLATOR;
    // 创建填充RingBuffer的EventFactory
    // Disruptor队列在初始化时会使用这个EventFactory来生成事件对象来填充满RingBuffer
    factory = mutable ? MUTABLE_FACTORY : FACTORY;
    // 创建Disruptor队列，指定生产者模式为MULTI，表示这是多生产者场景，一个AsyncLogger就是一个生产者
    disruptor = new Disruptor<>(factory, ringBufferSize, threadFactory, ProducerType.MULTI, waitStrategy);

    final ExceptionHandler<Log4jEventWrapper> errorHandler = DisruptorUtil.getAsyncLoggerConfigExceptionHandler();
    disruptor.setDefaultExceptionHandler(errorHandler);

    // 创建只有一个Log4jEventWrapperHandler的数组
    // Log4jEventWrapperHandler实现了EventHandler接口
    // 所以Log4j2里面使用的Disruptor队列只有单消费者消费
    final Log4jEventWrapperHandler[] handlers = {new Log4jEventWrapperHandler()};
    disruptor.handleEventsWith(handlers);

    LOGGER.debug("Starting AsyncLoggerConfig disruptor for this configuration with ringbufferSize={}, "
            + "waitStrategy={}, exceptionHandler={}...", disruptor.getRingBuffer().getBufferSize(), waitStrategy
            .getClass().getSimpleName(), errorHandler);
    // 启动Disruptor队列
    disruptor.start();
    super.start();
}

在AsyncLoggerConfigDisruptor的start()方法中主要就是在进行Disruptor队列的创建和启动，所以如果使用了AsyncLogger，那么存储日志消息元素的Disruptor队列在初始化LoggerContext时就会被创建并启动。

现在看一下每一个AsyncLogger是如何向Disruptor队列添加日志消息的。首先观察一下一个AsyncLogger的具体内容。

那么每一个AsyncLogger都持有一个AsyncLoggerConfig，所以可知AsyncLogger打印日志会通过AsyncLoggerConfig来打印，下面看一下AsyncLogger的log()方法，如下所示。

protected void log(final LogEvent event, final LoggerConfigPredicate predicate) {
    // 只有predicate为ALL，ASYNC_LOGGER_ENTERED为false以及当前AsyncLogger有Appender时才打印
    // predicate表示允许的日志打印类型，有ALL，ASYNCHRONOUS_ONLY和SYNCHRONOUS_ONLY三种
    // ASYNC_LOGGER_ENTERED是和线程绑定的原子布尔值，即同一线程只能串行的调用logToAsyncDelegate()方法向Disruptor队列添加日志消息
    if (predicate == LoggerConfigPredicate.ALL &&
            ASYNC_LOGGER_ENTERED.get() == Boolean.FALSE && hasAppenders()) {
        ASYNC_LOGGER_ENTERED.set(Boolean.TRUE);
        try {
            super.log(event, LoggerConfigPredicate.SYNCHRONOUS_ONLY);
            // 异步日志打印
            logToAsyncDelegate(event);
        } finally {
            ASYNC_LOGGER_ENTERED.set(Boolean.FALSE);
        }
    } else {
        super.log(event, predicate);
    }
}

在AsyncLogger的log()方法中，只有同时满足如下条件才执行异步日志打印。

当前打印动作是全类型打印，即predicate等于LoggerConfigPredicate.ALL。LoggerConfigPredicate一共有三种枚举值，LoggerConfigPredicate.ASYNCHRONOUS_ONLY表示仅异步打印，LoggerConfigPredicate.SYNCHRONOUS_ONLY表示仅同步打印，LoggerConfigPredicate.ALL表示同步异步都可以；
ASYNC_LOGGER_ENTERED的get()方法返回false。ASYNC_LOGGER_ENTERED是一个类型为ThreadLocal<Boolean>的变量，即同一线程只能串行的调用logToAsyncDelegate()方法向Disruptor队列添加日志消息；
当前AsyncLogger有Appender。

满足上述三点条件后，就会调用logToAsyncDelegate()方法来将日志消息添加到Disruptor队列中，看一下其实现。

private void logToAsyncDelegate(final LogEvent event) {
    if (!isFiltered(event)) {
        populateLazilyInitializedFields(event);
        // 这里的delegate就是AsyncLoggerConfigDisruptor
        // 通过AsyncLoggerConfigDisruptor将日志消息放入Disruptor的RingBuffer中
        if (!delegate.tryEnqueue(event, this)) {
            // Disruptor容量满时执行策略类的逻辑，这里与AsyncAppender中的策略是一致的
            handleQueueFull(event);
        }
    }
}

上述方法会调用AsyncLoggerConfigDisruptor的tryEnqueue()方法将日志消息添加到Disruptor队列中，如下所示。

public boolean tryEnqueue(final LogEvent event, final AsyncLoggerConfig asyncLoggerConfig) {
    final LogEvent logEvent = prepareEvent(event);
    // 从Disruptor对象中取出RingBuffer，然后将日志消息添加到RingBuffer中并发布
    return disruptor.getRingBuffer().tryPublishEvent(translator, logEvent, asyncLoggerConfig);
}

日志消息添加到Disruptor队列实际就是将日志消息LogEvent发布到Disruptor的RingBuffer中，后续消费者就能够从RingBuffer消费日志消息并基于Appender打印日志。

现在最后分析消费者线程的启动和消费逻辑。已知在初始化Log4j2的LoggerContext时会完成Disruptor队列的创建和启动，实际就是在Disruptor启动也就是Disruptor的start()方法执行时，会将消费者线程运行起来，这里的消费者是BatchEventProcessor，其本质是一个Runnable，所以最终会调用到BatchEventProcessor的run()方法，在run()方法中会循环的从Disruptor对象的RingBuffer中获取消息元素并将消息元素交由EventHandler处理，整个这一块儿逻辑是属于Disruptor队列的逻辑，这里不再赘述，但是处理消息的EventHandler是由Log4j2提供的Log4jEventWrapperHandler，这个在前面的分析中已经知道，所以看一下Log4jEventWrapperHandler的onEvent()方法。

public void onEvent(final Log4jEventWrapper event, final long sequence, final boolean endOfBatch)
        throws Exception {
    event.event.setEndOfBatch(endOfBatch);
    // 从Log4jEventWrapper中将AsyncLoggerConfig获取出来并在当前线程中完成日志打印
    event.loggerConfig.logToAsyncLoggerConfigsOnCurrentThread(event.event);
    event.clear();

    notifyIntermediateProgress(sequence);
}

void logToAsyncLoggerConfigsOnCurrentThread(final LogEvent event) {
    // 调用AsyncLoggerConfig的log()方法来打印日志
    // 有两点需要注意：
    // 1. 这里的log()方法和添加日志消息到队列中的log()方法是同一个
    // 2. 允许的打印行为被指定为LoggerConfigPredicate.ASYNCHRONOUS_ONLY，即同步打印
    log(event, LoggerConfigPredicate.ASYNCHRONOUS_ONLY);
}

protected void log(final LogEvent event, final LoggerConfigPredicate predicate) {
    if (predicate == LoggerConfigPredicate.ALL &&
            ASYNC_LOGGER_ENTERED.get() == Boolean.FALSE && hasAppenders()) {
        ASYNC_LOGGER_ENTERED.set(Boolean.TRUE);
        try {
            super.log(event, LoggerConfigPredicate.SYNCHRONOUS_ONLY);
            logToAsyncDelegate(event);
        } finally {
            ASYNC_LOGGER_ENTERED.set(Boolean.FALSE);
        }
    } else {
        // 调用父对象也就是LoggerConfig来打印日志，后续就是同步日志打印流程了
        super.log(event, predicate);
    }
}

Log4jEventWrapperHandler的onEvent()方法中，会将消费到的日志消息最终调用到和这条日志绑定的AsyncLoggerConfig的log()方法来打印日志，与生产消息的时候调用到AsyncLoggerConfig#log方法不同，这时调用AsyncLoggerConfig#log方法传入的predicate为LoggerConfigPredicate.ASYNCHRONOUS_ONLY，所以会直接调用AsyncLoggerConfig的父对象LoggerConfig来打印日志，后续就是同步打印日志的流程，这里不再赘述。

总结

当使用AsyncLogger来实现异步日志打印时，存储日志元素的队列为Disruptor高性能队列，该队列相较于传统的阻塞队列，优势如下。

使用RingBuffer环形数组存储元素，且在初始化队列时会将数组元素全部初始化出来，实现对象循环利用，避免频繁垃圾回收；
通过填充缓存行的方式避免了伪共享，充分利用缓存带来的效率提升；
使用CAS操作代替加锁操作，避免加解锁带来的性能损耗。

使用Disruptor作为阻塞队列是Log4j2性能提升的一大重要原因。

其次，所有AsyncLogger是共用同一个Disruptor队列的，每个AsyncLogger作为生产者可以并发的向Disruptor中添加日志元素，同时在消费者端存在一个消费者循环的从Disruptor中消费日志元素，每一条被消费的日志元素会被消费者调用到和这条日志绑定的LoggerConfig来完成打印，也就是可以理解为有多个生产者向Disruptor队列中生产日志元素，然后只有一个消费者从Disruptor队列消费日志元素并调用Appender完成日志打印，整个过程可以用下图进行示意和总结。

日志-log4j2基于AsyncLogger的异步日志打印

前言

正文

总结

半夏之沫

引用和评论

数据库连接池-Druid数据库连接池源码解析

告别ELK，APO提供基于ClickHouse开箱即用的高效日志方案——APO 0.6.0发布

spring使用@Async注解导致循环依赖问题异常的排查

tklog ：Rust灵活高效日志管理

Dolphinscheduler Slf4j MDC Task日志打印

spdlog 学习笔记-0

MySQL日志