1. 程式人生 > >log4j2非同步日誌解讀(二)AsyncLogger

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());
            // 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萬訂單的高效能佇列。