开启掘金成长之旅!这是我参与「掘金日新计划 · 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实际为AsyncLoggerContext,AsyncLoggerContext继承于LoggerContext,类图如下所示。
在一文搞懂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.contextSelector为AsyncLoggerContextSelector时,LoggerContextFactory中的selector的类型为AsyncLoggerContextSelector,再往下就会基于AsyncLoggerContextSelector加载一个未启动的AsyncLoggerContext(继承于LoggerContext),未启动的AsyncLoggerContext内容结构如下所示。
拿到AsyncLoggerContext后,就会调用到AsyncLoggerContext的start() 方法完成上下文启动,如下所示。
@Override
public void start() {
// 创建Disruptor队列并启动
loggerDisruptor.start();
// 解析配置文件得到Configuration,并创建Appender,Logger等
super.start();
}
AsyncLoggerContextSelector的start() 方法中会先将Disruptor队列创建出来,然后调用父类LoggerContext的start() 方法,LoggerContext的start() 方法主要就是找到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程序默认队列大小为4096 | web程序默认队列大小为262144,非web程序默认队列大小为4096 |
消费者等待策略 | TimeoutBlockingWaitStrategy,超时时间是10ms | TimeoutBlockingWaitStrategy,超时时间是10ms |
线程工厂 | Log4jThreadFactory | Log4jThreadFactory |
填充RingBuffer的工厂 | 创建RingBufferLogEvent的EventFactory | 创建Log4jEventWrapper的EventFactory |
错误处理器 | AsyncLoggerDefaultExceptionHandler | AsyncLoggerConfigDefaultExceptionHandler |
消费者 | 基于RingBufferLogEventHandler创建1 个消费者 | 基于Log4jEventWrapperHandler创建1 个消费者 |
那么结合上表,可知在全量异步模式下,一条日志在Disruptor队列中是以RingBufferLogEvent形式存放,且处理RingBufferLogEvent的Handler为RingBufferLogEventHandler。
还有一点需要注意,非web应用中,Disruptor大小有两种默认值,如下所示。
log4j2.enable.threadlocals == true ? 4096 : 262144
log4j2.enable.threadlocals为true时(默认),表示开启Threadlocal的使用,此时可以复用日志对象从而减少GC行为的发生,此时默认队列大小为4096。如果将log4j2.enable.threadlocals设置为false,则会部分禁用Threadlocal,每条日志打印都会创建日志对象,此时队列大小为262144。但如果是web应用,则log4j2.enable.threadlocals配置会失效,此时默认会部分禁用Threadlocal,故web应用队列大小默认是262144。
现在对本节内容做一下小结。即配置log4j2.contextSelector=AsyncLoggerContextSelector后,Log4j2在初始化阶段会做什么。
- 构建异步日志打印上下文。Log4j2在初始化阶段并构建日志打印器上下文时的上下文选择器为AsyncLoggerContextSelector,从而构建出AsyncLoggerContext上下文,表示启用全量异步日志打印;
- 启动后台异步日志打印线程。启动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,然后调用TranslatorType的log() 方法。首先是TranslatorType,有两种,如下所示。
- threadLocalTranslatorType。向Disruptor队列发布元素时,会使用RingBufferLogEventTranslator来发布,且RingBufferLogEventTranslator是存放在AsyncLogger的一个ThreadLocal类型的字段中,故一个线程会复用一个RingBufferLogEventTranslator,能够减少GC的次数;
- varargTranslatorType。向Disruptor队列发布元素时,是基于可变参数的形式来发布元素,此时的Translator就是AsyncLogger自己(AsyncLogger实现了EventTranslatorVararg接口),这种方式能够避免在ThreadLocal中存放任何对象,避免内存泄漏。
下面先看threadLocalTranslatorType的log() 方法的实现,如下所示。
@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拿到RingBufferLogEventTranslator(RingBufferLogEventTranslator继承了EventTranslator接口,可以用于向Disruptor队列发布元素),然后填充RingBufferLogEventTranslator的属性,例如基本属性level,message,location等和打印日志的线程的线程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队列,如果队列未满,就会最终调用到RingBufferLogEventTranslator的translateTo() 方法来完成元素发布,如果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元素,打印日志的后台线程,就能够看到这个元素并消费。
现在再看一下varargTranslatorType的log() 方法的实现,如下所示。
@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。
至此,业务线程打印日志的流程分析完毕。有如下注意点。
- 默认不拿方法位置信息。全量异步模式下,所有日志打印器都是AsyncLogger,此时默认includeLocation属性为false,则不会获取打印日志的方法的位置信息。如果在全量异步模式下,要拿方法位置信息,需要:首先配置日志打印器的includeLocation属性为true,然后还要求日志打印器的Appender中的PatternLayout有
%l
等格式符; - 日志添加到Disruptor队列后就返回。全量异步模式下,业务线程中打印一条日志时,仅需要将这一条日志封装成RingBufferLogEvent对象并添加到Disruptor队列中即可,实际的日志打印交由后台线程来完成,因此可以减少业务线程打印日志的时间,提高业务线程的吞吐量。
四. 后台消费者线程打印日志
已知消费者线程在初始化AsyncLoggerContext时就已经启动,故消费者BatchEventProcessor的run() 方法在初始化AsyncLoggerContext时就会被调用,一旦Disruptor队列中有可消费日志元素,那么在BatchEventProcessor的run() 方法中就会将这个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);
}
在RingBufferLogEvent的execute() 方法中,就是使用AsyncLogger持有的PrivateConfig进行实际的日志打印,后续流程和同步日志打印中使用PrivateConfig打印日志是一样的,具体可以参见一文搞懂Log4j2的同步日志打印一文。
一句话小结就是:后台消费者线程消费到RingBufferLogEvent后,会使用AsyncLogger持有的PrivateConfig来打印RingBufferLogEvent中的内容。
总结
全量异步日志打印示意图如下所示。
所谓异步日志打印,实际就是将打印日志时最终涉及到的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 天,点击查看活动详情