乐趣区

关于log4j2:日志log4j2基于AsyncLogger的异步日志打印

jiezi

前言

在日志 -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()办法中，只有同时满足如下条件才执行异步日志打印。

  1. 以后打印动作是全类型打印，即 predicate 等于 LoggerConfigPredicate.ALL。LoggerConfigPredicate 一共有三种枚举值，LoggerConfigPredicate.ASYNCHRONOUS_ONLY示意仅异步打印，LoggerConfigPredicate.SYNCHRONOUS_ONLY示意仅同步打印，LoggerConfigPredicate.ALL示意同步异步都能够；
  2. ASYNC_LOGGER_ENTERED的 get() 办法返回 false。ASYNC_LOGGER_ENTERED 是一个类型为 ThreadLocal<Boolean> 的变量，即同一线程只能串行的调用 logToAsyncDelegate() 办法向 Disruptor 队列增加日志音讯；
  3. 以后 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 高性能队列，该队列相较于传统的阻塞队列，劣势如下。

  1. 应用 RingBuffer 环形数组存储元素，且在初始化队列时会将数组元素全副初始化进去，实现对象循环利用，防止频繁垃圾回收；
  2. 通过填充缓存行的形式防止了伪共享，充分利用缓存带来的效率晋升；
  3. 应用 CAS 操作代替加锁操作，防止加解锁带来的性能损耗。

应用 Disruptor 作为阻塞队列是 Log4j2 性能晋升的一大重要起因。

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

退出移动版