log4j2異步日誌解讀（二）AsyncLogger

前文已經講了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());
            // 一、DefaultAsyncQueueFullPolicy---等待隊列，轉爲同步操做策略
            // 二、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>

 

總結

一、Log4j 2的異步記錄日誌在必定程度上提供更好的吞吐量，可是一旦隊列已滿，appender線程須要等待，這個時候就須要設置等待策略，AsyncAppender是依賴於消費者最序列最後的消費者，會持續等待。至於異步性能圖能夠看下官方提供的吞吐量比較圖，差別很明顯。

二、由於AsyncAppender是採用Disruptor，經過環形隊列無阻塞隊列做爲緩衝，多生產者多線程的競爭是經過CAS實現，無鎖化實現，能夠下降極端大的日誌量時候的延遲尖峯，Disruptor 但是號稱一個線程裏每秒處理600萬訂單的高性能隊列。