关于log4j2:日志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实现日志打印，整个过程能够用下图进行示意和总结。