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

21次阅读

共计 9946 个字符,预计需要花费 25 分钟才能阅读完成。

前言

在日志 -log4j2 日志框架源码学习一文中,对 Log4j2 的整体构造和同步打印流程进行了一个初步学习,本篇文章将对 Log4j2 异步打印流程进行学习。在同步日志打印中,利用业务逻辑与日志打印在一个线程中,利用后续业务逻辑须要期待日志打印实现能力继续执行,而异步日志打印中,利用业务逻辑与日志打印在不同线程中,Log4j2有专门的线程来实现日志打印而不会阻塞利用后续业务逻辑的执行。Log4j2提供了两种形式来配置异步日志打印,别离是 AsyncAppenderAsyncLogger,本篇文章先对 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,也就持有了nameMyAsync的异步 Appender,那么在打印日志时,最终会调用到异步Appenderappend()办法,这里理论会调用到 AsyncAppenderappend()办法,如下所示。

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,这里看一下XmlConfigurationstart()办法,如下所示。

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

XmlConfigurationstart()办法中,会遍历配置文件中配置的所有 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();}

AsyncAppenderstart() 办法首先会依据配置文件中的 <AppenderRef> 标签的值将给 AsyncAppender 援用的 Appender 获取进去,而后和阻塞队列一起创立AsyncAppenderEventDispatcher,该类的类图如下所示。

所以 AsyncAppenderEventDispatcher 实质是一个 Thread 对象,因而调用其 start() 办法后,AsyncAppenderEventDispatcherrun() 办法就会运行起来,看一下 AsyncAppenderEventDispatcherrun()办法的实现,如下所示。

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援用的 AppendernameMyConsoleConsoleAppendernameMyFileRollingFileAppender,所以每条被生产的日志都会被这两个Appender 打印。那么至此就晓得了生产阻塞队列中的日志的线程的启动是在 LoggerContext 初始化时启动每个 Appender 的时候。

当初回到 AsyncAppenderstart()办法,其中有一行代码是创立阻塞队列满时的 AsyncQueueFullPolicy 策略类,如下所示。

asyncQueueFullPolicy = AsyncQueueFullPolicyFactory.create();

所以持续跟进 AsyncQueueFullPolicyFactorycreate()办法,如下所示。

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 接口的某个实现类的全限定名,此时应用这个实现类作为阻塞队列满时的策略类。

最初剖析一下 DefaultAsyncQueueFullPolicyDiscardingAsyncQueueFullPolicy这两个策略类的实现,首先是 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() 办法来将日志增加到阻塞队列中,这一操作将会阻塞以后线程。上面看一下 DiscardingAsyncQueueFullPolicygetRoute()办法,如下所示。

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 的异步日志打印流程图如下所示。

正文完
 0