关于log4j2:日志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>
        <!-- 配置两个失常的Appedner -->
        <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>

        <!-- 让异步Appedner援用失常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的异步日志打印流程图如下所示。