log4j2非同步日誌解讀(二)AsyncLogger
前文已經講了log4j2的AsyncAppender的實現【log4j2非同步日誌解讀(一)AsyncAppender】,今天我們看看AsyncLogger的實現。
看了這個圖,應該很清楚AsyncLogger呼叫Disruptor,然後直接返回。至於高效能佇列 這裡已經展開講了是如何實現的。
AsyncLogger的呼叫流程
我們來看看AsyncLogger的呼叫流程,log.info()首先會呼叫抽象類AbstractLogger,然後呼叫了Logger的logMessage。
//Logger.java @Override public voidlogMessage(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, finalLevel 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萬訂單的高效能佇列。