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

前言

在日志-log4j2日志框架源码学习一文中，对Log4j2的整体结构和同步打印流程进行了一个初步学习，本篇文章将对Log4j2异步打印流程进行学习。在同步日志打印中，应用业务逻辑与日志打印在一个线程中，应用后续业务逻辑需要等待日志打印完成才能继续执行，而异步日志打印中，应用业务逻辑与日志打印在不同线程中，Log4j2有专门的线程来完成日志打印而不会阻塞应用后续业务逻辑的执行。Log4j2提供了两种方式来配置异步日志打印，分别是AsyncAppender和AsyncLogger，本篇文章先对AsyncAppender进行学习。

Log4j2版本：2.17.1

正文

首先需要搭建示例工程，在pom文件中引入Log4j2的依赖。

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

}

使用AsyncAppender的方式来配置异步日志打印，是基于<Async>标签来配置并得到异步Appender，打印日志时待打印的日志会被添加到异步Appender的阻塞队列中，然后由一个专门的后台线程消费阻塞队列中的待打印日志，这里的阻塞队列是ArrayBlockingQueue。使用AsyncAppender的方式的配置的一个例子如下所示。

<?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>

        <!-- 让异步Appender引用正常Appender -->
        <Async name="MyAsync">
            <AppenderRef ref="MyConsole"/>
            <AppenderRef ref="MyFile"/>
        </Async>
    </Appenders>

    <Loggers>
        <!-- 让根日志打印器引用异步Appender -->
        <Root level="INFO">
            <Appender-ref ref="MyAsync"/>
        </Root>
    </Loggers>
</Configuration>

通过上述的配置，在测试程序中的logger会继承使用根日志打印器的LoggerConfig，也就持有了name为MyAsync的异步Appender，那么在打印日志时，最终会调用到异步Appender的append()方法，这里实际会调用到AsyncAppender的append()方法，如下所示。

public void append(final LogEvent logEvent) {
    if (!isStarted()) {
        throw new IllegalStateException("AsyncAppender " + getName() + " is not active");
    }
    // 将MutableLogEvent转换为Log4jLogEvent
    // includeLocation控制是否将打印日志的代码行号传递给Log4jLogEvent
    final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation);
    InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage());
    // 调用transfer()方法将待打印日志添加到阻塞队列中
    if (!transfer(memento)) {
        if (blocking) {
            if (AbstractLogger.getRecursionDepth() > 1) {
                AsyncQueueFullMessageUtil.logWarningToStatusLogger();
                // 如果阻塞队列已满且正处于递归调用中，则在当前线程中直接调用Appender打印日志
                logMessageInCurrentThread(logEvent);
            } else {
                // 如果阻塞队列已满但不处于递归调用中，则根据配置的AsyncQueueFullPolicy来决定如何处理该条日志
                final EventRoute route = asyncQueueFullPolicy.getRoute(dispatcher.getId(), memento.getLevel());
                route.logMessage(this, memento);
            }
        } else {
            error("Appender " + getName() + " is unable to write primary appenders. queue is full");
            logToErrorAppenderIfNecessary(false, memento);
        }
    }
}

在上述append()方法中，实际完成的事情就是将待打印日志添加到阻塞队列中，这里的阻塞队列是ArrayBlockingQueue，如果添加到阻塞队列成功，则append()方法执行完毕，如果失败，则会再判断当前是否是处于递归调用中，如果是处于递归调用中，则直接在当前线程中调用Appender来完成日志打印，这样的日志打印是一个同步打印，如果没有处于递归调用中，则会使用配置的AsyncQueueFullPolicy来决定如何处理该条日志，根据配置的AsyncQueueFullPolicy的不同，处理策略有丢弃，排队，阻塞或者直接打印等。

到这里有两个地方还需要进行讨论，一是上述append()方法完成的事情是在应用线程里往阻塞队列offer()待打印日志，那么从阻塞队列里消费待打印日志的打印线程是什么时候启动又如何工作的呢；二是当阻塞队列满时，配置的AsyncQueueFullPolicy具体会如何处理待打印日志。下面将对上述两个问题继续进行讨论。

已知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();
    }
    if (hasAsyncLoggers()) {
        asyncLoggerConfigDisruptor.start();
    }
    final Set<LoggerConfig> alreadyStarted = new HashSet<>();
    for (final LoggerConfig logger : loggerConfigs.values()) {
        logger.start();
        alreadyStarted.add(logger);
    }
    // 遍历配置文件中配置的Appender并启动
    for (final Appender appender : appenders.values()) {
        appender.start();
    }
    if (!alreadyStarted.contains(root)) {
        root.start();
    }
    super.start();
    LOGGER.debug("Started configuration {} OK.", this);
}

在XmlConfiguration的start()方法中，会遍历配置文件中配置的所有Appender并启动，在本小节的示例配置文件中，配置的Appender如下所示。

那么配置的异步Appender也会在这里被调用start()方法，其实现如下所示。

public void start() {
    // 拿到配置的所有Appender的map
    final Map<String, Appender> map = config.getAppenders();
    final List<AppenderControl> appenders = new ArrayList<>();
    // 遍历异步Appender的AppenderRef，并根据AppenderRef去所有Appender的map中拿到为异步Appender引用的Appender
    for (final AppenderRef appenderRef : appenderRefs) {
        final Appender appender = map.get(appenderRef.getRef());
        if (appender != null) {
            appenders.add(new AppenderControl(appender, appenderRef.getLevel(), appenderRef.getFilter()));
        } else {
            LOGGER.error("No appender named {} was configured", appenderRef);
        }
    }
    if (errorRef != null) {
        final Appender appender = map.get(errorRef);
        if (appender != null) {
            errorAppender = new AppenderControl(appender, null, null);
        } else {
            LOGGER.error("Unable to set up error Appender. No appender named {} was configured", errorRef);
        }
    }
    if (appenders.size() > 0) {
        // 创建AsyncAppenderEventDispatcher
        // AsyncAppenderEventDispatcher实际上是一个Thread
        dispatcher = new AsyncAppenderEventDispatcher(
                getName(), errorAppender, appenders, queue);
    } else if (errorRef == null) {
        throw new ConfigurationException("No appenders are available for AsyncAppender " + getName());
    }
    // 创建队列满时的处理策略
    asyncQueueFullPolicy = AsyncQueueFullPolicyFactory.create();

    // 启动AsyncAppenderEventDispatcher线程
    dispatcher.start();
    super.start();
}

AsyncAppender的start()方法首先会根据配置文件中的<AppenderRef>标签的值将给AsyncAppender引用的Appender获取出来，然后和阻塞队列一起创建AsyncAppenderEventDispatcher，该类的类图如下所示。

所以AsyncAppenderEventDispatcher本质是一个Thread对象，因此调用其start()方法后，AsyncAppenderEventDispatcher的run()方法就会运行起来，看一下AsyncAppenderEventDispatcher的run()方法的实现，如下所示。

public void run() {
    LOGGER.trace("{} has started.", getName());
    // 开始消费阻塞队列中的日志并打印
    dispatchAll();
    // 线程如果被停止，则调用dispatchRemaining()保证阻塞队列中的日志全部被打印
    dispatchRemaining();
}

private void dispatchAll() {
    while (!stoppedRef.get()) {
        LogEvent event;
        try {
            // 从阻塞队列消费日志，队列如果为空则一直等待直到有日志为止
            event = queue.take();
        } catch (final InterruptedException ignored) {
            // 重新设置中断标志位
            interrupt();
            break;
        }
        // 只有在调用了stop()方法后，才会往阻塞队列中添加STOP_EVENT
        // 所以消费到STOP_EVENT后，就退出循环
        if (event == STOP_EVENT) {
            break;
        }
        event.setEndOfBatch(queue.isEmpty());
        dispatch(event);
    }
    LOGGER.trace("{} has stopped.", getName());
}

void dispatch(final LogEvent event) {

    // 将日志分发给引用的每个Appender进行打印
    boolean succeeded = false;
    for (int appenderIndex = 0; appenderIndex < appenders.size(); appenderIndex++) {
        final AppenderControl control = appenders.get(appenderIndex);
        try {
            control.callAppender(event);
            succeeded = true;
        } catch (final Throwable error) {
            LOGGER.trace(
                    "{} has failed to call appender {}",
                    getName(), control.getAppenderName(), error);
        }
    }

    if (!succeeded && errorAppender != null) {
        try {
            errorAppender.callAppender(event);
        } catch (final Throwable error) {
            LOGGER.trace(
                    "{} has failed to call the error appender {}",
                    getName(), errorAppender.getAppenderName(), error);
        }
    }

}

由上述代码可知，专门有一个线程（AsyncAppenderEventDispatcher）循环的从阻塞队列中消费日志，每消费一条日志，就会将该条日志分发给引用的Appender进行打印，本示例中，AsyncAppender引用的Appender有name为MyConsole的ConsoleAppender和name为MyFile的RollingFileAppender，所以每条被消费的日志都会被这两个Appender打印。那么至此就知道了消费阻塞队列中的日志的线程的启动是在LoggerContext初始化时启动每个Appender的时候。

现在回到AsyncAppender的start()方法，其中有一行代码是创建阻塞队列满时的AsyncQueueFullPolicy策略类，如下所示。

asyncQueueFullPolicy = AsyncQueueFullPolicyFactory.create();

所以继续跟进AsyncQueueFullPolicyFactory的create()方法，如下所示。

public static AsyncQueueFullPolicy create() {
    // 从系统变量中将log4j2.AsyncQueueFullPolicy获取出来
    final String router = PropertiesUtil.getProperties().getStringProperty(PROPERTY_NAME_ASYNC_EVENT_ROUTER);
    // 如果没有配置log4j2.AsyncQueueFullPolicy的值或其值为Default，则使用DefaultAsyncQueueFullPolicy作为阻塞队列满时的策略类
    if (router == null || isRouterSelected(
            router, DefaultAsyncQueueFullPolicy.class, PROPERTY_VALUE_DEFAULT_ASYNC_EVENT_ROUTER)) {
        return new DefaultAsyncQueueFullPolicy();
    }
    // 如果配置的log4j2.AsyncQueueFullPolicy的值为Discard，则使用DiscardingAsyncQueueFullPolicy作为阻塞队列满时的策略类
    if (isRouterSelected(
            router, DiscardingAsyncQueueFullPolicy.class, PROPERTY_VALUE_DISCARDING_ASYNC_EVENT_ROUTER)) {
        return createDiscardingAsyncQueueFullPolicy();
    }
    // 如果配置的log4j2.AsyncQueueFullPolicy的值既不是Default也不是Discard
    // 则认为这个值是某个AsyncQueueFullPolicy接口的实现类的全限定名，使用这个类作为阻塞队列满时的策略类
    return createCustomRouter(router);
}

由上可知，阻塞队列满时的策略类是由配置的log4j2.AsyncQueueFullPolicy的值来决定，当配置为Default时，策略类为DefaultAsyncQueueFullPolicy，当配置为Discard时，策略类为DiscardingAsyncQueueFullPolicy，如果既不是Default，也不是Discard，则log4j2.AsyncQueueFullPolicy的值应该是AsyncQueueFullPolicy接口的某个实现类的全限定名，此时使用这个实现类作为阻塞队列满时的策略类。

最后分析一下DefaultAsyncQueueFullPolicy和DiscardingAsyncQueueFullPolicy这两个策略类的实现，首先是DefaultAsyncQueueFullPolicy，其getRoute()方法如下所示。

public EventRoute getRoute(final long backgroundThreadId, final Level level) {

    Thread currentThread = Thread.currentThread();
    // 如果当前线程是后台线程，则直接在当前线程中调用Appender打印日志
    if (currentThread.getId() == backgroundThreadId
            || currentThread instanceof Log4jThread) {
        return EventRoute.SYNCHRONOUS;
    }
    // 否则调用阻塞队列的put()方法来将日志添加到阻塞队列中，这一操作会阻塞当前线程
    return EventRoute.ENQUEUE;
}

DefaultAsyncQueueFullPolicy策略类的策略很简单，判断当前线程是否是后台线程（AsyncAppenderEventDispatcher），如果是的话，就直接调用Appender来打印日志，如果不是则调用阻塞队列的put()方法来将日志添加到阻塞队列中，这一操作将会阻塞当前线程。下面看一下DiscardingAsyncQueueFullPolicy的getRoute()方法，如下所示。

public EventRoute getRoute(final long backgroundThreadId, final Level level) {
    // 如果当前日志级别小于或等于阈值日志级别，则丢弃该条日志
    if (level.isLessSpecificThan(thresholdLevel)) {
        if (discardCount.getAndIncrement() == 0) {
            LOGGER.warn("Async queue is full, discarding event with level {}. " +
                    "This message will only appear once; future events from {} " +
                    "are silently discarded until queue capacity becomes available.",
                    level, thresholdLevel);
        }
        return EventRoute.DISCARD;
    }
    // 如果当前日志级别大于阈值日志级别，则调用DefaultAsyncQueueFullPolicy策略类来处理该条日志
    return super.getRoute(backgroundThreadId, level);
}

DiscardingAsyncQueueFullPolicy首先会判断当前这条日志的级别是否小于或等于阈值日志级别，如果是则丢弃这条日志，阈值日志级别由系统变量log4j2.DiscardThreshold配置，如果没有配置则默认的阈值日志级别是INFO，如果当前这条日志的级别大于阈值日志级别，则使用DefaultAsyncQueueFullPolicy默认策略类来处理这条日志。实际上DiscardingAsyncQueueFullPolicy继承于DefaultAsyncQueueFullPolicy，在默认策略的基础上扩展增强了根据阈值日志级别来丢弃日志的策略。

至此，基于AsyncAppender进行异步日志打印的源码分析完毕。

总结

当使用AsyncAppender来异步打印日志时，每个AsyncAppender持有一个ArrayBlockingQueue，并且每个AsyncAppender还会启动一个后台线程来消费阻塞队列中的待打印日志，后台线程每消费一条待打印日志，就会遍历当前AsyncAppender持有的Appender来完成日志打印。

基于AsyncAppender的异步日志打印流程图如下所示。