作者：京東集團-京東零售-技術與數據中臺-共享技術部-流量技術組 王麗。

引言

在程序開發過程中，幾乎任何一個應用程序都會通過打印日志來記錄跟蹤程序運行情況，打印日志信息不僅可以讓我們詳細的了解程序內部的運行情況，更能在排查問題是提供詳細的異常信息，為我們解決問題提供重要的線索。

最近在梳理項目運行情況時發現有個應用每天的日志量較大，在高峰時打印日志較為密集，發現配置日志打印使用的是Apache log4j2同步方式，那果斷換成log4j2異步方式啊。但是都說異步方式打印日志性能好，強大且高效，具體性能可以提升多少，和同步方式相比差距有多大，為何大家更偏愛異步日志，今天通過數據對比，揭秘一下真實的原因。

log4j2的三種打印日志方式

Apache log4j2有三種打印日志方式，分別是同步方式、AsyncAppender異步及AsyncLogger異步方式，接下來分別針對這三種方式的用法進行簡單的介紹。

1、Sync同步方式

同步記錄日志是指當輸出日志時，必須等待日志輸出語句執行完畢后，才能執行后面的業務邏輯語句。

在輸出日志時，會將日志信息轉換為日志事件LogEvent對象，然后將LogEvent對象傳入對應的Appender中，由對應的Appender調用appender()方法將日志信息寫入文件。

下面的代碼是在LogConfig類中的log()方法中，創建LogEvent對象，調用processLogEvent()方法將LogEvent對象傳入對應的Appender中。

publicvoid?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?{//?省略部分代碼}final?LogEvent?logEvent?=?logEventFactoryinstanceof?LocationAwareLogEventFactory ?((LocationAwareLogEventFactory)?logEventFactory).createEvent(loggerName,?marker,?fqcn, requiresLocation() ?StackLocatorUtil.calcLocation(fqcn) :?null,?level,?data,?props,?t) :logEventFactory.createEvent(loggerName,?marker,?fqcn,?level,?data,?props,?t);try?{log(logEvent, LoggerConfigPredicate.ALL);}?finally?{ReusableLogEventFactory.release(logEvent);}}protectedvoid?log(final?LogEvent?event,?final?LoggerConfigPredicate?predicate) {if?(!isFiltered(event)) {processLogEvent(event,?predicate);}}privatevoid?processLogEvent(final?LogEvent?event,?final?LoggerConfigPredicate?predicate) {event.setIncludeLocation(isIncludeLocation());if?(predicate.allow(this)) {callAppenders(event);}logParent(event,?predicate);}protectedvoid?callAppenders(final?LogEvent?event) {final?AppenderControl[]?controls?=?appenders.get();//noinspection?ForLoopReplaceableByForEachfor?(inti?= 0;?i?<?controls.length;?i++) {controls[i].callAppender(event);}}

在抽象類AbstractOutputStreamAppender中的appender()方法，最后調用directEncodeEvent()將日志信息寫入文件。

/*** Actual writing occurs here.*?<p>* Most subclasses of?<code>AbstractOutputStreamAppender</code>?will need to override this method.*?</p>**?@param?event The LogEvent.*/@Overridepublicvoid?append(final?LogEvent?event) {try?{tryAppend(event);}?catch?(final?AppenderLoggingException?ex) {error("Unable to write to stream "?+?manager.getName() +?" for appender "?+ getName(),?event,?ex);throwex;}}privatevoid?tryAppend(final?LogEvent?event) {if?(Constants.ENABLE_DIRECT_ENCODERS) {directEncodeEvent(event);}?else?{writeByteArrayToManager(event);}}protectedvoid?directEncodeEvent(final?LogEvent?event) {getLayout().encode(event,?manager);if?(this.immediateFlush?||?event.isEndOfBatch()) {manager.flush();}}

log4j2.xml配置如下：

<Configuration?status="ERROR"><Appenders><RollingFile?name="LOG-ACCESS"?fileName="logs/access.log"?immediateFlush="true"><PatternLayout?pattern="[%-5p %l %t %d{yyyy-MM-dd HH:mm:ss,SSS}]? %m%n"?/></RollingFile></Appenders><Loggers><logger?name="com.log.test"?level="INFO"?additivity="false"><AppenderRef?ref="LOG-ACCESS"?/></logger></Loggers></Configuration>

2、AsyncAppender 異步方式

Appender官方文檔上給出的定義是“Appenders are responsible for delivering LogEvents to their destination.”，它的作用是將日志事件傳遞到指定目標。Log4j2提供了多種Appender，其中AsyncAppender是一種能將日志事件異步寫入文件的Appender。

AsyncAppender在官方文檔上的介紹如下：

The AsyncAppender accepts references to other Appenders and causes LogEvents to be written to them on a separate Thread. Note that exceptions while writing to those Appenders will be hidden from the application. The AsyncAppender should be configured after the appenders it references to allow it to shut down properly. By default, AsyncAppender uses java.util.concurrent.ArrayBlockingQueue which does not require any external libraries. Note that multi-threaded applications should exercise care when using this appender as such: the blocking queue is susceptible to lock contention.

簡單來說，AsyncAppender的異步打印做了兩件事，先把日志事件放到ArrayBlockingQueue隊列，然后單獨的線程讀取隊列中的日志事件將其傳遞給其他引用的Appender，由這些Appender將日志寫入文件。

查看AsyncAppender源碼，可以看到他的成員變量中有一個ArrayBlockingQueue隊列，隊列默認大小為1024，一個單獨的線程類AsyncThread，還有它引用的Appender數組。

publicfinalclass?AsyncAppender?extends?AbstractAppender {privatestaticfinalintDEFAULT_QUEUE_SIZE?= 1024;privatefinal?BlockingQueue<LogEvent>?queue;privatefinal?AppenderRef[]?appenderRefs;private?AsyncThread?thread;//?省略其他成員變量及成員方法相關代碼}

首先來看AsyncAppender是如何將日志事件存入隊列的，下面是AsyncAppender類中的append(LogEvent logEvent)方法，可以看到在appender方法中調用了私有方法transfer(LogEvent memento)，將日志事件存入在隊列中。

@Overridepublicvoid?append(final?LogEvent?logEvent) {if?(!isStarted()) {thrownew?IllegalStateException("AsyncAppender "?+ getName() +?" is not active");}final?Log4jLogEvent?memento?= Log4jLogEvent.createMemento(logEvent,?includeLocation);InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage());if?(!transfer(memento)) {//?省略隊列阻塞等待相關處理}?else?{error("Appender "?+ getName() +?" is unable to write primary appenders. queue is full");logToErrorAppenderIfNecessary(false,?memento);}}}privateboolean?transfer(final?LogEvent?memento) {returnqueueinstanceof?TransferQueue? ((TransferQueue<LogEvent>)?queue).tryTransfer(memento):?queue.offer(memento);}

然后再看看AsyncThread是如何獲取隊列中的LogEvent的，并將日志事件傳遞給其他引用的Appender。

@Overridepublicvoid?append(final?LogEvent?logEvent) {if?(!isStarted()) {thrownew?IllegalStateException("AsyncAppender "?+ getName() +?" is not active");}final?Log4jLogEvent?memento?= Log4jLogEvent.createMemento(logEvent,?includeLocation);InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage());if?(!transfer(memento)) {//?省略隊列阻塞等待相關處理}?else?{error("Appender "?+ getName() +?" is unable to write primary appenders. queue is full");logToErrorAppenderIfNecessary(false,?memento);}}}privateboolean?transfer(final?LogEvent?memento) {returnqueueinstanceof?TransferQueue? ((TransferQueue<LogEvent>)?queue).tryTransfer(memento):?queue.offer(memento);}

在AsyncThread的run()方法中，循環阻塞獲取隊列中的LogEvent，獲取日志事件后，在callAppenders(LogEvent event)方法中，將日志事件傳遞到它引用的Appender，調用對應Appender的appender(LogEvent event)方法，這樣就完成了異步將日志事件寫入文件。

AsyncAppender異步打印日志方式是在配置文件中添加<Async>標簽，在<logger>標簽中，引用該appender。

log4j2.xml配置如下：

@Overridepublicvoid?append(final?LogEvent?logEvent) {if?(!isStarted()) {thrownew?IllegalStateException("AsyncAppender "?+ getName() +?" is not active");}final?Log4jLogEvent?memento?= Log4jLogEvent.createMemento(logEvent,?includeLocation);InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage());if?(!transfer(memento)) {//?省略隊列阻塞等待相關處理}?else?{error("Appender "?+ getName() +?" is unable to write primary appenders. queue is full");logToErrorAppenderIfNecessary(false,?memento);}}}privateboolean?transfer(final?LogEvent?memento) {returnqueueinstanceof?TransferQueue? ((TransferQueue<LogEvent>)?queue).tryTransfer(memento):?queue.offer(memento);}

3、AsyncLogger 異步方式

AsyncLogger的異步記錄器是Log4j2的一個新特性，可以通過在單獨的線程中執行I/O操作來提高應用程序的性能。其內部使用了disruptor框架，其底層數據結構為無鎖環形隊列，每次日志信息保存在隊列中，另一個線程將隊列中日志寫入文件。

AsyncLogger異步記錄器官方文檔上描述如下：

Asynchronous logging can improve your application's performance by executing the I/O operations in a separate thread. Log4j 2 makes a number of improvements in this area. Asynchronous Loggers are a new addition in Log4j 2. Their aim is to return from the call to Logger.log to the application as soon as possible. LMAX Disruptor technology. Asynchronous Loggers internally use the Disruptor, a lock-free inter-thread communication library, instead of queues, resulting in higher throughput and lower latency.

通過描述可以看出，AsyncLogger主要是通過使用LMAX disruptor框架代替隊列，從而提高吞吐量，降低延遲。那么，disruptor框架到底是個什么呢，disruptor文檔上的介紹如下：

The best way to understand what the Disruptor is, is to compare it to something well understood and quite similar in purpose. In the case of the Disruptor this would be Java's BlockingQueue. Like a queue the purpose of the Disruptor is to move data (e.g. messages or events) between threads within the same process. However there are some key features that the Disruptor provides that distinguish it from a queue. They are: Multicast events to consumers, with consumer dependency graph. Pre-allocate memory for events. Optionally lock-free.

根據介紹可以看出disruptor框架是個高性能線程間消息傳遞庫，支持發送多播事件，基本上是無鎖狀態，會為事件提前分配內存空間。

disruptor框架的底層結構是環形緩沖區RingBuffer，當日志到達后，AsyncLogger的logMessage()方法會將日志信息轉換為RingBufferLogEventTranslator對象，然后調用public()方法將translator對象放入RingBuffer中。

privatefinal?TranslatorType?threadLocalTranslatorType?=?new?TranslatorType() {@Overridevoid?log(String?fqcn, Level?level, Marker?marker, Message?message, Throwable?thrown) {logWithThreadLocalTranslator(fqcn,?level,?marker,?message,?thrown);}};@Overridepublicvoid?logMessage(final?String?fqcn,?final?Level?level,?final?Marker?marker,?final?Message?message,final?Throwable?thrown) {getTranslatorType().log(fqcn,?level,?marker,?message,?thrown);}privatevoid?logWithThreadLocalTranslator(final?String?fqcn,?final?Level?level,?final?Marker?marker,final?Message?message,?final?Throwable?thrown) {// Implementation note: this method is tuned for performance. MODIFY WITH CARE!final?RingBufferLogEventTranslator?translator?= getCachedTranslator();initTranslator(translator,?fqcn,?level,?marker,?message,?thrown);initTranslatorThreadValues(translator);publish(translator);}privatevoid?publish(final?RingBufferLogEventTranslator?translator) {if?(!loggerDisruptor.tryPublish(translator)) {handleRingBufferFull(translator);}}

disruptor的單線程批量處理BatchEventProcessor會從RingBuffer中讀取存入的事件，回調EventHandler的onEvent()方法。在RingBufferLogEventHandler的onEvent()方法中，將日志信息寫入文件。

@Overridepublicvoid?onEvent(final?RingBufferLogEvent?event,?finallongsequence,finalbooleanendOfBatch)?throws?Exception {try?{event.execute(endOfBatch);}finally?{event.clear();// notify the BatchEventProcessor that the sequence has progressed.// Without this callback the sequence would not be progressed// until the batch has completely finished.notifyCallback(sequence);}}//?RingBufferLogEvent的execute()方法/*** Event processor that reads the event from the?ringbuffer?can call this method.**?@param?endOfBatch flag to indicate if this is the last event in a batch from the RingBuffer*/publicvoid?execute(finalbooleanendOfBatch) {this.endOfBatch?=?endOfBatch;asyncLogger.actualAsyncLog(this);}

AsyncLogger依賴disruptor框架，因此需要在classpath路徑下需要額外添加disruptor的jar包。AsyncLogger有兩種方式全異步方式和混合同步異步方式。

（1）全異步方式，需要設置系統屬性，指定log4j2.contextSelector值為org.apache.logging.log4j.core.async.AsyncLoggerContextSelector，配置文件中使用<Logger>或<Root>標簽

（2）混合同步異步方式無需設置系統屬性log4j2.contextSelector，在配置文件中使用<AsyncLogger>或<AsyncRoot>標簽代替<Logger>或<Root>標簽。

混合同步異步方式log4j2.xml配置如下：

<Configuration?status="ERROR"><Appenders><RollingFile??name="LOG-ACCESS"?fileName="logs/access.log"?immediateFlush="true"><PatternLayout?pattern="[%-5p %l %t %d{yyyy-MM-dd HH:mm:ss,SSS}]? %m%n"?/></RollingFile></Appenders><Loggers><AsyncLogger?name=" com.log.test"?level="INFO"?additivity="false"><AppenderRef?ref="LOG-ACCESS"/></AsyncLogger></Loggers></Configuration>

現在我們大致知道了這三種日志打印方式的用法了，但是幾個問題仍然需要解答：

1、三種日志打印方式對系統性能上差距有多大。

2、同步方式和異步方式在內存使用方面有什么差別。

3、兩種異步方式底層隊列實現方式不同，究竟哪個性能更好。

接下來我們就要通過測試數據來尋找答案。

實測數據對比

為了更好的比較Log4j2的三種方式記錄日志信息對系統性能帶來的差別，進行了壓力測試，以此來根據測試結果針對不同的應用場景，在保證日志記錄詳盡的前提下，選擇性能最優的日志記錄方式。

本次測試使用2核CPU，內存大小4G，50G硬盤的服務器，通過調用http接口，在接口內打印108字節大小的日志，壓測過程中，get方式請求接口，tomcat最大線程數設置為10個，并發用戶數400個，每次持續時間為6分鐘，記錄CPU使用率、內存使用率、磁盤寫速度、磁盤寫次數、接口TPS、接口響應時間等指標。使用各組件的版本信息如下：

• JDK：1.8

• Spring Boot : 2.1.3.RELEASE

• Log4j2 ：2.13.1

• Disruptor：3.4.2

1、單個Appender

壓測過程中，初始CPU差別不大，400個并發用戶數使機器CPU使用率達到100%。

在內存使用情況上，同步方式和AsyncAppender方式差別不大，而AsyncLogger方式的內存使用率略高于另外兩種2%。

單個Appender的情況下，兩種異步方式的線程數比同步方式多1個，可以看出，異步的方式會創建出新的線程來寫入日志。

?

AsyncAppender的磁盤使用情況和接口每秒調用量都優于AsyncLogger，兩種異步記錄日志方式的接口每秒調用量是同步記錄日志方式的兩倍左右，可以看出異步記錄日志方式的系統性能明顯優于同步記錄日志方式。

2、3個Appender

從CPU和內存的使用情況來看，在CPU利用率100%時，AsyncLogger方式的內存使用率依然略高于另外兩種方式，和單個Appender的情況差不多，可以看出，AsyncLogger在內存使用上與Appender的個數并無關系。

3個Appender的時候，AsyncAppender的線程數比單個Appender增加了2個，可以看出，每個AsyncAppender 都會創建出一個線程處理日志輸出；而 AsyncLogger的線程數和單個Appender的線程數相同，說明AsyncLogger方式共用1個線程來處理日志輸出。

?

由于每新增一個Appender，AsyncAppender就會為其創建一個線程，由于線程數越多，ArrayBlockingQueue阻塞隊列受鎖爭用的影響，線程上下文切換的開銷就越大，相比之下，AsyncAppender在Appender越多的情況下優勢會慢慢減弱。當有3個Appender時，從磁盤使用情況和接口每秒調用量兩個指標來看，AsyncLogger的表現都優于AsyncAppender。

3、6個Appender

?

結合前面幾個圖，可以看出，當有6個Appender的時候，AsyncAppender的線程數比單個Appender增加了5個，使用AsyncLogger的系統性能和使用AsyncAppender的系統性能有了明顯的優勢，也就是說當Appender越多時，AsyncLogger的性能優勢在三種日志記錄方式中表現的越明顯。

4、immediateFlush

在閱讀官方文檔過程中，發現異步記錄日志章節中，文檔上特別標注了immediateFlush參數，這個參數是配置每次寫入日志時是否立即寫入磁盤，于是又添加了一組對比實驗，測試這個參數對性能帶來的影響。官方文檔上對這個參數的介紹如下：

When set to true - the default, each write will be followed by a flush. This will guarantee the data is written to disk but could impact performance. Flushing after every write is only useful when using this appender with synchronous loggers. Asynchronous loggers and appenders will automatically flush at the end of a batch of events, even if immediateFlush is set to false. This also guarantees the data is written to disk but is more efficient.

默認情況下，該值為true，當值為false時，會在buffer滿或異步隊列為空的時候刷新寫入磁盤。

下圖比較的是在3個Appender的情況下AsyncLogger配置immediateFlush值為true和值為false的性能對比。

不難看出當immediateFlush參數配置為false時，關閉立即刷新后，磁盤使用情況和接口每秒調用量只是略高于立即刷新，兩者的差距并不是很大，在使用過程中，可以根據自身實際需求選擇。

小結

1、在線程使用方面，log4j2的同步方式使用和業務邏輯相同的線程處理日志輸出；AsyncAppender內部使用ArrayBlockingQueue隊列，對于每一個AsyncAppender都會創建一個線程處理日志輸出；AsyncLogger內部使用了disruptor框架，其底層數據結構為無鎖環形隊列，使用一個單獨線程處理日志輸出。

2、在日志內容較多，打印日志頻繁的情況下，兩種異步日志記錄方式會優于同步方式。

3、如果系統并非頻繁打印日志，只是在異常情況或極端情況下打印幾條日志信息，根據實際生產經驗，同步和兩種異步方式之間體現不出差距，可以選擇使用同步方式記錄日志信息。

總結

以上是生活随笔為你收集整理的Log4j2异步日志背后的数字的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。