详解Log4j2的全量异步模式

1,168

开启掘金成长之旅!这是我参与「掘金日新计划 · 2 月更文挑战」的第 10 天,点击查看活动详情

前言

详解Log4j2混合异步中的异步Appender一文中,分析了Log4j2如何基于AsyncAppender来实现混合异步日志打印,又在详解Log4j2混合异步中的异步Logger一文中,分析了Log4j2如何基于AsyncLogger来实现混合异步日志打印。这两篇文章分析的都是Log4j2的混合异步模式,该模式能够提供灵活的异步日志打印,但其实Log4j2真正的精髓在于其提供的全量异步日志打印,Log4j2真正的快,其实就是在开启全量异步模式之后。

本篇文章将分析Log4j2的全量异步日志打印的实现原理,将会涉及部分Disruptor队列的相关概念,如果不熟悉Disruptor队列,可以先阅读深入理解Disruptor队列的快一文来了解相关概念。

Log4j2版本:2.17.1

正文

一. 示例工程

日志打印程序如下。

public class LogExecute {

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

    public static void main(String[] args) {
        logger.info("Log execute success.");
    }

}

log4j2.xml配置文件如下所示。

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

<Configuration>
    <Appenders>
        <Console name="MyConsole" target="SYSTEM_OUT">
            <ThresholdFilter level="DEBUG" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %p [%l] %m%n"/>
        </Console>
    </Appenders>

    <Loggers>
        <Root level="INFO" includeLocation="true">
            <Appender-ref ref="MyConsole"/>
        </Root>
    </Loggers>
</Configuration>

上述是同步日志打印时的一份简单配置,并未使用到异步标签例如<AsyncLogger>,<Async>等,而要开启全量异步日志打印,仅需要添加如下JVM参数。

-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

最后,引入的依赖如下所示。

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

特别注意Disruptor框架的版本,如果使用Log4j2的版本是2.9及以上,那么需求的Disruptor的版本要是3.3.4及以上。

二. AsyncLoggerContext初始化

开启全量异步日志打印后,Log4j2初始化时得到的LoggerContext实际为AsyncLoggerContextAsyncLoggerContext继承于LoggerContext,类图如下所示。

AsyncLoggerContext类图

一文搞懂Log4j2的同步日志打印一文中已知,初始化LoggerContext是通过LogManager#factory字段来完成。LogManager#factory字段是一个LoggerContextFactory对象,其在LogManager的静态代码块中完成初始化,初始化时会调用到LoggerContextFactory的构造函数,如下所示。

public Log4jContextFactory() {
    this(createContextSelector(), createShutdownCallbackRegistry());
}

private static ContextSelector createContextSelector() {
    try {
        // 根据配置的Log4jContextSelector变量来决定Selector类型
        final ContextSelector selector = Loader.newCheckedInstanceOfProperty(Constants.LOG4J_CONTEXT_SELECTOR,
                ContextSelector.class);
        if (selector != null) {
            return selector;
        }
    } catch (final Exception e) {
        LOGGER.error("Unable to create custom ContextSelector. Falling back to default.", e);
    }
    // 如果没配置Log4jContextSelector变量,则返回一个ClassLoaderContextSelector
    return new ClassLoaderContextSelector();
}

也就是当配置了log4j2.contextSelectorAsyncLoggerContextSelector时,LoggerContextFactory中的selector的类型为AsyncLoggerContextSelector,再往下就会基于AsyncLoggerContextSelector加载一个未启动的AsyncLoggerContext(继承于LoggerContext),未启动的AsyncLoggerContext内容结构如下所示。

未启动的AsyncLoggerContext

拿到AsyncLoggerContext后,就会调用到AsyncLoggerContextstart() 方法完成上下文启动,如下所示。

@Override
public void start() {
    // 创建Disruptor队列并启动
    loggerDisruptor.start();
    // 解析配置文件得到Configuration,并创建Appender,Logger等
    super.start();
}

AsyncLoggerContextSelectorstart() 方法中会先将Disruptor队列创建出来,然后调用父类LoggerContextstart() 方法,LoggerContextstart() 方法主要就是找到Log4j2配置文件并解析为Configuration,然后启动Configuration,这在一文搞懂Log4j2的同步日志打印一文中已经有分析,这里不再赘述。下面主要看一下全量异步模式下,Disruptor队列如何创建,以及全量异步模式和基于AsyncLogger混合模式下的Disruptor队列有何不同。AsyncLoggerDisruptor#start方法如下所示。

public synchronized void start() {

    // 省略
    
    setStarting();
    // web程序默认队列大小为262144
    // 非web程序默认队列大小为4096
    ringBufferSize = DisruptorUtil.calculateRingBufferSize("AsyncLogger.RingBufferSize");
    // 等待策略,默认是TimeoutBlockingWaitStrategy,超时时间是10ms
    // 该策略用于Disruptor队列的消费者等待可消费元素,等待超过超时时间,抛出TimeoutException
    final WaitStrategy waitStrategy = DisruptorUtil.createWaitStrategy("AsyncLogger.WaitStrategy");

    // 线程工厂
    final ThreadFactory threadFactory = new Log4jThreadFactory("AsyncLogger[" + contextName + "]", true, Thread.NORM_PRIORITY) {
        @Override
        public Thread newThread(final Runnable r) {
            final Thread result = super.newThread(r);
            backgroundThreadId = result.getId();
            return result;
        }
    };
    // 队列满时的策略,默认策略是排队
    // 向Disruptor队列添加LogEvent失败时会执行策略逻辑
    asyncQueueFullPolicy = AsyncQueueFullPolicyFactory.create();

    // 创建Disruptor队列
    disruptor = new Disruptor<>(RingBufferLogEvent.FACTORY, ringBufferSize, threadFactory, ProducerType.MULTI,
            waitStrategy);

    // 创建并注册ExceptionHandler
    // 通常用于处理异步打印日志时抛出的异常
    final ExceptionHandler<RingBufferLogEvent> errorHandler = DisruptorUtil.getAsyncLoggerExceptionHandler();
    disruptor.setDefaultExceptionHandler(errorHandler);

    // 基于RingBufferLogEventHandler创建并注册消费者
    // 只有一个消费者,故只有一个后台线程异步打印日志
    final RingBufferLogEventHandler[] handlers = {new RingBufferLogEventHandler()};
    disruptor.handleEventsWith(handlers);

    // 启动Disruptor队列
    disruptor.start();

    super.start();
}

下表是全量异步模式和基于AsyncLogger混合模式下的Disruptor队列的一个对比。

Disruptor组件全量异步模式基于AsyncLogger混合模式
队列大小web程序默认队列大小为262144,非web程序默认队列大小为4096web程序默认队列大小为262144,非web程序默认队列大小为4096
消费者等待策略TimeoutBlockingWaitStrategy,超时时间是10msTimeoutBlockingWaitStrategy,超时时间是10ms
线程工厂Log4jThreadFactoryLog4jThreadFactory
填充RingBuffer的工厂创建RingBufferLogEventEventFactory创建Log4jEventWrapperEventFactory
错误处理器AsyncLoggerDefaultExceptionHandlerAsyncLoggerConfigDefaultExceptionHandler
消费者基于RingBufferLogEventHandler创建1个消费者基于Log4jEventWrapperHandler创建1个消费者

那么结合上表,可知在全量异步模式下,一条日志在Disruptor队列中是以RingBufferLogEvent形式存放,且处理RingBufferLogEventHandlerRingBufferLogEventHandler

还有一点需要注意,非web应用中,Disruptor大小有两种默认值,如下所示。

log4j2.enable.threadlocals == true ? 4096 : 262144

log4j2.enable.threadlocalstrue时(默认),表示开启Threadlocal的使用,此时可以复用日志对象从而减少GC行为的发生,此时默认队列大小为4096。如果将log4j2.enable.threadlocals设置为false,则会部分禁用Threadlocal,每条日志打印都会创建日志对象,此时队列大小为262144。但如果是web应用,则log4j2.enable.threadlocals配置会失效,此时默认会部分禁用Threadlocal,故web应用队列大小默认是262144。

现在对本节内容做一下小结。即配置log4j2.contextSelector=AsyncLoggerContextSelector后,Log4j2在初始化阶段会做什么。

  1. 构建异步日志打印上下文Log4j2在初始化阶段并构建日志打印器上下文时的上下文选择器为AsyncLoggerContextSelector,从而构建出AsyncLoggerContext上下文,表示启用全量异步日志打印;
  2. 启动后台异步日志打印线程。启动AsyncLoggerContext时,就会创建并启动Disruptor队列,此时后台异步打印日志的线程就会启动。

三. 业务线程打印日志

本节将分析当在业务线程中,调用Logger.info 方法打印一条日志时,在全量日异步志模式下,是怎样的一个行为表现。

首先调用到Log4jLogger#info(String),如下所示。

public void info(final String format) {
    logger.logIfEnabled(FQCN, Level.INFO, null, format);
}

然后会调用到AbstractLogger#logIfEnabled(String, Level, Marker, String),如下所示。

public void logIfEnabled(final String fqcn, final Level level, final Marker marker, final String message) {
    if (isEnabled(level, marker, message)) {
        logMessage(fqcn, level, marker, message);
    }
}

然后会调用到AbstractLogger#logMessage(String, Level, Marker, String),如下所示。

protected void logMessage(final String fqcn, final Level level, final Marker marker, final String message) {
    final Message msg = messageFactory.newMessage(message);
    logMessageSafely(fqcn, level, marker, msg, msg.getThrowable());
}

然后会调用到AbstractLogger#logMessageSafely,如下所示。

private void logMessageSafely(final String fqcn, final Level level, final Marker marker, final Message message,
                              final Throwable throwable) {
    try {
        logMessageTrackRecursion(fqcn, level, marker, message, throwable);
    } finally {
        ReusableMessageFactory.release(message);
    }
}

然后会调用到AbstractLogger#logMessageTrackRecursion,如下所示。

private void logMessageTrackRecursion(final String fqcn,
                                      final Level level,
                                      final Marker marker,
                                      final Message message,
                                      final Throwable throwable) {
    try {
        incrementRecursionDepth();
        // 先调用getLocation()方法拿打印日志的方法位置信息
        tryLogMessage(fqcn, getLocation(fqcn), level, marker, message, throwable);
    } finally {
        decrementRecursionDepth();
    }
}

在上述方法中,会先调用到AbstractLogger#getLocation方法来拿打印日志的方法位置信息。在Log4j2中通常是根据new Throwable().getStackTrace() 拿到堆栈信息,然后通过fqcn去堆栈中匹配最终定位得到打印日志的方法的位置信息。通常,如果日志打印器的includeLocation属性为true,且日志打印器使用的Appender中的PatternLayout%l等格式符,则在上面的AbstractLogger#getLocation方法中就会将打印日志的方法的位置信息获取出来,只要日志打印器的includeLocation属性为true,或者日志打印器使用的Appender中的PatternLayout没有%l等格式符,那么在上面的AbstractLogger#getLocation方法中以及后续的流程中,都不会去获取打印日志的方法位置信息。还有一点需要注意,异步时,无论是全量异步还是混合异步,日志打印器的includeLocation属性默认为false,因此想要在异步模式下打印出方法位置信息,需要显式的配置日志打印器的includeLocation属性为true

AbstractLogger#logMessageTrackRecursion方法中会继续调用到AbstractLogger#tryLogMessage方法,如下所示。

private void tryLogMessage(final String fqcn,
                           final StackTraceElement location,
                           final Level level,
                           final Marker marker,
                           final Message message,
                           final Throwable throwable) {
    try {
        log(level, marker, fqcn, location, message, throwable);
    } catch (final Throwable t) {
        handleLogMessageException(t, fqcn, message);
    }
}

其实一条日志的打印流程中,在调用到AbstractLogger#tryLogMessage方法之前,全量异步模式和其它模式没什么区别,但是当在AbstractLogger#tryLogMessage方法中调用log() 方法时,在全量异步模式下就会调用到AsyncLogger重写的log() 方法,如下所示。

public void log(final Level level, final Marker marker, final String fqcn, final StackTraceElement location,
                final Message message, final Throwable throwable) {
    getTranslatorType().log(fqcn, location, level, marker, message, throwable);
}

上述会先调用getTranslatorType() 方法返回一个TranslatorType,然后调用TranslatorTypelog() 方法。首先是TranslatorType,有两种,如下所示。

  1. threadLocalTranslatorType。向Disruptor队列发布元素时,会使用RingBufferLogEventTranslator来发布,且RingBufferLogEventTranslator是存放在AsyncLogger的一个ThreadLocal类型的字段中,故一个线程会复用一个RingBufferLogEventTranslator,能够减少GC的次数;
  2. varargTranslatorType。向Disruptor队列发布元素时,是基于可变参数的形式来发布元素,此时的Translator就是AsyncLogger自己(AsyncLogger实现了EventTranslatorVararg接口),这种方式能够避免在ThreadLocal中存放任何对象,避免内存泄漏。

下面先看threadLocalTranslatorTypelog() 方法的实现,如下所示。

@Override
void log(String fqcn, StackTraceElement location, Level level, Marker marker, Message message,
         Throwable thrown) {
    logWithThreadLocalTranslator(fqcn, location, level, marker, message, thrown);
}

会调用到AsyncLogger#logWithThreadLocalTranslator(String, StackTraceElement, Level, Marker, Message, Throwable) 方法,如下所示。

private void logWithThreadLocalTranslator(final String fqcn, final StackTraceElement location, final Level level,
                                          final Marker marker, final Message message, final Throwable thrown) {
    // 从ThreadLocal中拿到RingBufferLogEventTranslator
    final RingBufferLogEventTranslator translator = getCachedTranslator();
    // 为RingBufferLogEventTranslator设置一些日志的基本信息,例如level,message,location等
    initTranslator(translator, fqcn, location, level, marker, message, thrown);
    // 为RingBufferLogEventTranslator设置打印日志的线程的相关信息,包括线程Id,线程名称和线程优先级
    initTranslatorThreadValues(translator);
    // 使用RingBufferLogEventTranslator来发布日志元素
    publish(translator);
}

上述方法首先从ThreadLocal拿到RingBufferLogEventTranslatorRingBufferLogEventTranslator继承了EventTranslator接口,可以用于向Disruptor队列发布元素),然后填充RingBufferLogEventTranslator的属性,例如基本属性levelmessagelocation等和打印日志的线程的线程Id线程名称线程优先级,最后就是调用AsyncLogger#publish方法将需要打印的日志添加到Disruptor队列中。下面看一下AsyncLogger#publish方法的实现。

private void publish(final RingBufferLogEventTranslator translator) {
    // 通过AsyncLoggerDisruptor#tryPublish添加日志到Disruptor队列
    if (!loggerDisruptor.tryPublish(translator)) {
        // 执行Disruptor队列满时的策略逻辑
        handleRingBufferFull(translator);
    }
}

首先就是通过AsyncLoggerDisruptor#tryPublish添加日志到Disruptor队列,如果队列未满,就会最终调用到RingBufferLogEventTranslatortranslateTo() 方法来完成元素发布,如果Disruptor队列满了,那么会调用AsyncLogger#handleRingBufferFull(RingBufferLogEventTranslator) 方法来执行相应的策略逻辑。简单看下RingBufferLogEventTranslator#translateTo的逻辑,如下所示。

@Override
public void translateTo(final RingBufferLogEvent event, final long sequence) {
    try {
        // 队列未满时,会将可以发布的RingBufferLogEvent传递到RingBufferLogEventTranslator
        // 在这里会使用RingBufferLogEventTranslator的属性来填充RingBufferLogEvent的属性
        event.setValues(asyncLogger, loggerName, marker, fqcn, level, message, thrown,
                INJECTOR.injectContextData(null, (StringMap) event.getContextData()), contextStack,
                threadId, threadName, threadPriority, location, clock, nanoClock);
    } finally {
        // 最后清空RingBufferLogEventTranslator的属性
        clear();
    }
}

也就是将RingBufferLogEventTranslator中的属性填充到RingBufferLogEvent中,然后清空RingBufferLogEventTranslator中的属性,上述方法执行完毕后,Disruptor队列就会发布这个RingBufferLogEvent元素,打印日志的后台线程,就能够看到这个元素并消费。

现在再看一下varargTranslatorTypelog() 方法的实现,如下所示。

@Override
void log(String fqcn, StackTraceElement location, Level level, Marker marker, Message message,
         Throwable thrown) {
    logWithVarargTranslator(fqcn, location, level, marker, message, thrown);
}

会调用到AsyncLogger#logWithVarargTranslator(String, StackTraceElement, Level, Marker, Message, Throwable),如下所示。

private void logWithVarargTranslator(final String fqcn, final StackTraceElement location, final Level level,
                                     final Marker marker, final Message message, final Throwable thrown) {
    final Disruptor<RingBufferLogEvent> disruptor = loggerDisruptor.getDisruptor();
    if (disruptor == null) {
        LOGGER.error("Ignoring log event after Log4j has been shut down.");
        return;
    }
    if (!isReused(message)) {
        InternalAsyncUtil.makeMessageImmutable(message);
    }
    // 调用RingBuffer#tryPublishEvent(EventTranslatorVararg<E>, Object...)方法来发布日志
    // 日志内容以可变参数的形式传入,且这里的EventTranslatorVararg就是AsyncLogger自己
    if (!disruptor.getRingBuffer().tryPublishEvent(this,
            this,
            location,
            fqcn,
            level,
            marker,
            message,
            thrown)) {
        // 队列满时,执行相应策略逻辑
        handleRingBufferFull(location, fqcn, level, marker, message, thrown);
    }
}

上述方法会通过RingBuffer#tryPublishEvent(EventTranslatorVararg, Object...) 方法将日志内容以可变参数的形式添加到Disruptor队列中,此时充当EventTranslatorVararg的角色就是AsyncLogger自己,下面看一下AsyncLogger#translateTo的实现。

@Override
public void translateTo(final RingBufferLogEvent event, final long sequence, final Object... args) {
    // 将可变参数具体化
    final AsyncLogger asyncLogger = (AsyncLogger) args[0];
    final StackTraceElement location = (StackTraceElement) args[1];
    final String fqcn = (String) args[2];
    final Level level = (Level) args[3];
    final Marker marker = (Marker) args[4];
    final Message message = (Message) args[5];
    final Throwable thrown = (Throwable) args[6];

    final ContextStack contextStack = ThreadContext.getImmutableStack();

    final Thread currentThread = Thread.currentThread();
    final String threadName = THREAD_NAME_CACHING_STRATEGY.getThreadName();
    // 将日志信息填充到RingBufferLogEvent中
    event.setValues(asyncLogger, asyncLogger.getName(), marker, fqcn, level, message, thrown,
            CONTEXT_DATA_INJECTOR.injectContextData(null, (StringMap) event.getContextData()),
            contextStack, currentThread.getId(), threadName, currentThread.getPriority(), location,
            CLOCK, nanoClock);
}

也就是将可变参数填充到Disruptor队列传递过来的RingBufferLogEvent中。

通常Translator默认是使用threadLocalTranslatorType

至此,业务线程打印日志的流程分析完毕。有如下注意点。

  1. 默认不拿方法位置信息。全量异步模式下,所有日志打印器都是AsyncLogger,此时默认includeLocation属性为false,则不会获取打印日志的方法的位置信息。如果在全量异步模式下,要拿方法位置信息,需要:首先配置日志打印器的includeLocation属性为true,然后还要求日志打印器的Appender中的PatternLayout%l等格式符;
  2. 日志添加到Disruptor队列后就返回。全量异步模式下,业务线程中打印一条日志时,仅需要将这一条日志封装成RingBufferLogEvent对象并添加到Disruptor队列中即可,实际的日志打印交由后台线程来完成,因此可以减少业务线程打印日志的时间,提高业务线程的吞吐量。

四. 后台消费者线程打印日志

已知消费者线程在初始化AsyncLoggerContext时就已经启动,故消费者BatchEventProcessorrun() 方法在初始化AsyncLoggerContext时就会被调用,一旦Disruptor队列中有可消费日志元素,那么在BatchEventProcessorrun() 方法中就会将这个RingBufferLogEvent对象传递给RingBufferLogEventHandler#onEvent方法来进行实际的日志打印,下面看一下RingBufferLogEventHandler#onEvent方法的实现。

@Override
public void onEvent(final RingBufferLogEvent event, final long sequence,
                    final boolean endOfBatch) throws Exception {
    try {
        // 如果RingBufferLogEvent的isPopulated()返回false
        // 表示这个RingBufferLogEvent在填充日志内容时发生了异常
        // 这种RingBufferLogEvent就不处理
        if (event.isPopulated()) {
            // 打日志
            event.execute(endOfBatch);
        }
    }
    finally {
        // 清空RingBufferLogEvent
        event.clear();
        notifyCallback(sequence);
    }
}

RingBufferLogEventHandler#onEvent方法会先判断当前RingBufferLogEvent是不是被完全填充(如果填充日志内容时发生异常会导致填充不完整),没有被完全填充的RingBufferLogEvent需要被忽略,完全填充的RingBufferLogEvent就调用其execute() 方法进行打印,如下所示。

public void actualAsyncLog(final RingBufferLogEvent event) {
    final LoggerConfig privateConfigLoggerConfig = privateConfig.loggerConfig;
    final List<Property> properties = privateConfigLoggerConfig.getPropertyList();

    if (properties != null) {
        onPropertiesPresent(event, properties);
    }

    // 实际走打印日志的流程,这一块儿和同步日志打印的流程是一样的
    privateConfigLoggerConfig.getReliabilityStrategy().log(this, event);
}

RingBufferLogEventexecute() 方法中,就是使用AsyncLogger持有的PrivateConfig进行实际的日志打印,后续流程和同步日志打印中使用PrivateConfig打印日志是一样的,具体可以参见一文搞懂Log4j2的同步日志打印一文。

一句话小结就是:后台消费者线程消费到RingBufferLogEvent后,会使用AsyncLogger持有的PrivateConfig来打印RingBufferLogEvent中的内容。

总结

全量异步日志打印示意图如下所示。

Log-Log4j2的全量异步日志打印示意图

所谓异步日志打印,实际就是将打印日志时最终涉及到的I/O操作放在一个单独的后台线程中执行,从而让业务线程能够快速的从Logger.log() 方法返回。

Log4j2提供了全量异步模式混合异步模式(异步Logger混合异步Appender)。全量异步性能最好混合异步灵活度高。要开启全量异步,仅需要添加如下JVM参数。

-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

但是切记,开启了全量异步后,就不要再使用混合异步了,不然会出现有两个后台打印日志的线程的情况,这会造成不必要的开销。

全量异步模式下,Log4j2初始化时,会创建并启动AsyncLoggerContext作为上下文,启动AsyncLoggerContext时就会创建并启动Disruptor队列,打印日志的后台线程也是在这时完成启动。

全量异步模式下,业务线程中打印日志时,默认不会带方法位置信息,除非配置日志打印器的includeLocation属性为true,并且日志打印器的Appender中的PatternLayout%l等格式符。


开启掘金成长之旅!这是我参与「掘金日新计划 · 2 月更文挑战」的第 10 天,点击查看活动详情