前文已经讲了log4j2的AsyncAppender的实现【log4j2异步日志解读(一)AsyncAppender】,今天我们看看AsyncLogger的实现。
看了这个图,应该很清楚AsyncLogger调用Disruptor,然后直接返回。至于高性能队列 这里已经展开讲了是如何实现的。
AsyncLogger的调用流程
我们来看看AsyncLogger的调用流程,log.info()首先会调用抽象类AbstractLogger,然后调用了Logger的logMessage。
//Logger.java
@Override
public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,
final Throwable t) {
final Message msg = message == null ? new SimpleMessage(Strings.EMPTY) : message;
final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();
strategy.log(this, getName(), fqcn, marker, level, msg, t);
}
strategy.log是调用了ReliabilityStrategy接口,日志事件传递到适当的appender的对象的接口,然后调用了LoggerConfig.log()方法,来创建有关记录消息的上下文信息。
//LoggerConfig.java
@PerformanceSensitive("allocation")
public void log(final String loggerName, final String fqcn, final Marker marker, final Level level,
final Message data, final Throwable t) {
List<Property> props = null;
if (!propertiesRequireLookup) {
props = properties;
} else {
if (properties != null) {
props = new ArrayList<>(properties.size());
final LogEvent event = Log4jLogEvent.newBuilder()
.setMessage(data)
.setMarker(marker)
.setLevel(level)
.setLoggerName(loggerName)
.setLoggerFqcn(fqcn)
.setThrown(t)
.build();
for (int i = 0; i < properties.size(); i++) {
final Property prop = properties.get(i);
final String value = prop.isValueNeedsLookup() // since LOG4J2-1575
? config.getStrSubstitutor().replace(event, prop.getValue()) //
: prop.getValue();
props.add(Property.createProperty(prop.getName(), value));
}
}
}
final LogEvent logEvent = logEventFactory.createEvent(loggerName, marker, fqcn, level, data, props, t);
try {
log(logEvent, LoggerConfigPredicate.ALL);
} finally {
// LOG4J2-1583 prevent scrambled logs when logging calls are nested (logging in toString())
ReusableLogEventFactory.release(logEvent);
}
}
接着我们来看AsyncLoggerConfig.logToAsyncDelegate()方法,首先会调用Disruptor,放入环形队列。如果环形队列阻塞,则执行等待策略。
//AsyncLoggerConfig.java
private void logToAsyncDelegate(LogEvent event) {
if (!isFiltered(event)) {
// Passes on the event to a separate thread that will call
// asyncCallAppenders(LogEvent).
populateLazilyInitializedFields(event);
if (!delegate.tryEnqueue(event, this)) {
//如果获取Disruptor队列需要等待则执行等待策略,这里类似AsyncAppender等待策略
handleQueueFull(event);
}
}
}
private void handleQueueFull(final LogEvent event) {
if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
// If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
AsyncQueueFullMessageUtil.logWarningToStatusLogger();
logToAsyncLoggerConfigsOnCurrentThread(event);
} else {
// otherwise, we leave it to the user preference
final EventRoute eventRoute = delegate.getEventRoute(event.getLevel());
// 1、DefaultAsyncQueueFullPolicy---等待队列,转为同步操作策略
// 2、DiscardingAsyncQueueFullPolicy---按照日志等级抛弃日志策略
eventRoute.logMessage(this, event);
}
}
然后再来看看Disruptor写入 的过程。LogEvent是记录消息的上下文信息的接口,然后调用tryPublishEvent去获取环形队列的位置,然后发布数据到环形队列上。
//AsyncLoggerConfigDisruptor.java
@Override
public boolean tryEnqueue(final LogEvent event, final AsyncLoggerConfig asyncLoggerConfig) {
final LogEvent logEvent = prepareEvent(event);
return disruptor.getRingBuffer().tryPublishEvent(translator, logEvent, asyncLoggerConfig);
}
日志的消费过程,定义RingBufferLogEventHandler类实现Disruptor的SequenceReportingEventHandler的onEvent方法,从ringbuffer读取事件进行处理。最后会调用该logger绑定的默认appender输出。
最后提供下笔者测试demo
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" monitorInterval="30">
<Appenders>
<RollingRandomAccessFile name="applicationAppender" fileName="./log/application.log"
filePattern="./log/$${date:yyyy-MM}/common-%d{yyyy-MM-dd}.log.gz"
append="false">
<PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%p] - %l - %m%n"/>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingRandomAccessFile>
<Console name="CONSOLE" target="SYSTEM_OUT">
<PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%p] %t - %l - %m%n"/>
</Console>
<!-- AsyncAppender配置 -->
<!--<Async name="asyncTest" blocking="true">-->
<!--<AppenderRef ref="applicationAppender"/>-->
<!--</Async>-->
</Appenders>
<Loggers>
<!-- AsyncLogger配置 -->
<AsyncLogger name="log4j2" >
<AppenderRef ref="applicationAppender"/>
</AsyncLogger>
<Root level="info">
<!--<AppenderRef ref="CONSOLE"/>-->
<AppenderRef ref="applicationAppender"/>
</Root>
<!--<Logger name="log4j2" level="debug" additivity="false" >-->
<!--<AppenderRef ref="CONSOLE"/>-->
<!--<AppenderRef ref="applicationAppender"/>-->
<!--</Logger>-->
</Loggers>
</Configuration>
总结
1、Log4j 2的异步记录日志在一定程度上提供更好的吞吐量,但是一旦队列已满,appender线程需要等待,这个时候就需要设置等待策略,AsyncAppender是依赖于消费者最序列最后的消费者,会持续等待。至于异步性能图可以看下官方提供的吞吐量比较图,差异很明显。
2、因为AsyncAppender是采用Disruptor,通过环形队列无阻塞队列作为缓冲,多生产者多线程的竞争是通过CAS实现,无锁化实现,可以降低极端大的日志量时候的延迟尖峰,Disruptor 可是号称一个线程里每秒处理600万订单的高性能队列。