Log4j中的异步Appender+Logger

前文已经讲了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去获取环形队列的位置，然后发布数据到环形队列上。这一块具体可以看笔者前文Disruptor源码分析，这里就不展开讨论。

//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万订单的高性能队列。

https://logging.apache.org/log4j/2.x/manual/appenders.html#AsyncAppender

 

log4j、logback、log4j2 历史和关系，我们就在这里不展开讲了。直接上干货，log4j2突出于其他日志的优势，异步日志实现。

看一个东西，首先看官网文档 ，因为前面文章已经讲解了disruptor源码，本文主要展开说说异步日志AsyncAppender和AsyncLogger（基于disruptor实现）。

AsyncLogger笔者下文展开讲。

 

一、AsyncAppender

 

我们先来看看AsyncApperder核心，就是logger将数据通过append方法放入到阻塞队列中，随后后台线程从队列中取出数据然后进行后续的操作。

那这样看来，就很简单了，一个append()方法，一个后台线程执行就是我们要看的核心代码了。围绕我们要看的类AsyncAppender，来看看类关系图。

一、放入队列

主要实现就是logger将数据通过append方法放入到阻塞队列中。

//AsyncAppender.java
    /**
     * Actual writing occurs here.
     *
     * @param logEvent The LogEvent.
     */
    @Override
    public void append(final LogEvent logEvent) {
        if (!isStarted()) {
            throw new IllegalStateException("AsyncAppender " + getName() + " is not active");
        }
        //创建Log4jLogEvent的对象memento
        final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation);
        InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage());
        //transfer(memento)将event放入队列
        //默认ArrayBlockingQueueFactory 大小1024
        if (!transfer(memento)) {
            if (blocking) {
                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();
                    logMessageInCurrentThread(logEvent);
                } else {
                    // delegate to the event router (which may discard, enqueue and block, or log in current thread)
                 
                    final EventRoute route = asyncQueueFullPolicy.getRoute(thread.getId(), memento.getLevel());
                    route.logMessage(this, memento);
                }
            } else {
                error("Appender " + getName() + " is unable to write primary appenders. queue is full");
                logToErrorAppenderIfNecessary(false, memento);
            }
        }
    }

    private boolean transfer(final LogEvent memento) {
        return queue instanceof TransferQueue
            ? ((TransferQueue<LogEvent>) queue).tryTransfer(memento)
            : queue.offer(memento);
    }

如流程图所示，首先会判断用户是否设置了blocking选项，默认是true，如果设置为false，则Appender直接会ToErrorAppender，如果用户没有配置或者配置为true，则会按照一定的策略来处理这些消息。策略可以分为2种，他们分别为：

1、DefaultAsyncQueueFullPolicy---等待队列，转为同步操作策略

public class DefaultAsyncQueueFullPolicy implements AsyncQueueFullPolicy {
    @Override
    public EventRoute getRoute(final long backgroundThreadId, final Level level) {

        // LOG4J2-471: prevent deadlock when RingBuffer is full and object
        // being logged calls Logger.log() from its toString() method
        if (Thread.currentThread().getId() == backgroundThreadId) {
            return EventRoute.SYNCHRONOUS;
        }
        return EventRoute.ENQUEUE;
    }

2、DiscardingAsyncQueueFullPolicy---按照日志等级抛弃日志策略

//DiscardingAsyncQueueFullPolicy.java
    @Override
    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;
        }
        return super.getRoute(backgroundThreadId, level);
    }

二、后台线程执行后续操作。

主要就是后台线程从队列中取出数据然后进行后续的操作。

//AsyncAppender.java
private class AsyncThread extends Log4jThread {

        private volatile boolean shutdown = false;
        private final List<AppenderControl> appenders;
        private final BlockingQueue<LogEvent> queue;

        public AsyncThread(final List<AppenderControl> appenders, final BlockingQueue<LogEvent> queue) {
            super("AsyncAppender-" + THREAD_SEQUENCE.getAndIncrement());
            this.appenders = appenders;
            this.queue = queue;
            setDaemon(true);
        }

        @Override
        public void run() {
            while (!shutdown) {
                LogEvent event;
                try {
                    event = queue.take();
                    if (event == SHUTDOWN_LOG_EVENT) {
                        shutdown = true;
                        continue;
                    }
                } catch (final InterruptedException ex) {
                    break; // LOG4J2-830
                }
                event.setEndOfBatch(queue.isEmpty());
                final boolean success = callAppenders(event);
                if (!success && errorAppender != null) {
                    try {
                        errorAppender.callAppender(event);
                    } catch (final Exception ex) {
                        // Silently accept the error.
                    }
                }
            }
            // Process any remaining items in the queue.
            LOGGER.trace("AsyncAppender.AsyncThread shutting down. Processing remaining {} queue events.",
                queue.size());
            int count = 0;
            int ignored = 0;
            while (!queue.isEmpty()) {
                try {
                    final LogEvent event = queue.take();
                    if (event instanceof Log4jLogEvent) {
                        final Log4jLogEvent logEvent = (Log4jLogEvent) event;
                        logEvent.setEndOfBatch(queue.isEmpty());
                        callAppenders(logEvent);
                        count++;
                    } else {
                        ignored++;
                        LOGGER.trace("Ignoring event of class {}", event.getClass().getName());
                    }
                } catch (final InterruptedException ex) {
                    // May have been interrupted to shut down.
                    // Here we ignore interrupts and try to process all remaining events.
                }
            }
            LOGGER.trace("AsyncAppender.AsyncThread stopped. Queue has {} events remaining. "
                + "Processed {} and ignored {} events since shutdown started.", queue.size(), count, ignored);
        }

    ...
}

该线程会一直尝试从阻塞队列中获取LogEvent，如果获取成功，调用AppenderRef所引用Appender的append方法。我们也可以看到，AsyncAppender实际上主要是类似于中转，日志异步化，当消息放入阻塞队列，返回成功，这样能够大幅提高日志记录的吞吐。用户可以在权衡性能与日志收集质量上进行权衡配置策略(设置blocking选项)，当然也可以设置不同类型的阻塞队列已到达更好的日志记录吞吐。

AsyncAppender配置参数  

https://logging.apache.org/log4j/2.x/manual/appenders.html#AsyncAppender

 

Log4j-1.2.17

Log4j中的AsyncAppender的实现原理

log4j里有个Appender：AsyncAppender，这个Appender是用于解决在某一时间里大量的日志信息进入Appender如何去处理的问题。AsyncAppender采用的方案是这样的，以下是AsyncAppender的工作原理图： 

 

AsyncAppender采用的是生产者消费者的模型进行异步地将Logging Event送到对应的Appender中。 
（1）生产者：外部应用了Log4j的系统的实时线程，实时将Logging Event传送进AsyncAppender里 
（2）中转：Buffer和DiscardSummary 
（3）消费者：Dispatcher线程和appenders 
  
工作原理： 
1）  Logging Event进入AsyncAppender，AsyncAppender会调用append方法，在append方法中会去把logging Event填入Buffer中，当消费能力不如生产能力时，AsyncAppender会把超出Buffer容量的Logging Event放到DiscardSummary中，作为消费速度一旦跟不上生成速度，中转buffer的溢出处理的一种方案。 
2）  AsyncAppender有个线程类Dispatcher，它是一个简单的线程类，实现了Runnable接口。它是AsyncAppender的后台线程。 
Dispatcher所要做的工作是： 
①  锁定Buffer，让其他要对Buffer进行操作的线程阻塞。 
②  看Buffer的容量是否满了，如果满了就将Buffer中的Logging Event全部取出，并清空Buffer和DiscardSummary；如果没满则等待Buffer填满Logging Event，然后notify Disaptcher线程。 
③  将取出的所有Logging Event交给对应appender进行后面的日志信息推送。 
以上是AsyncAppender类的两个关键点：append方法和Dispatcher类，通过这两个关键点实现了异步推送日志信息的功能，这样如果大量的Logging Event进入AsyncAppender，就可以游刃有余地处理这些日志信息了。