當(dāng)前位置：首頁 > 编程资源 > 编程问答 >内容正文

编程问答

Log4j2异步日志背后的数字

發(fā)布時間：2025/3/21 编程问答 31 豆豆

生活随笔收集整理的這篇文章主要介紹了 Log4j2异步日志背后的数字小編覺得挺不錯的,現(xiàn)在分享給大家,幫大家做個參考.

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

引言

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

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

log4j2的三種打印日志方式

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

1、Sync同步方式

同步記錄日志是指當(dāng)輸出日志時，必須等待日志輸出語句執(zhí)行完畢后，才能執(zhí)行后面的業(yè)務(wù)邏輯語句。

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

下面的代碼是在LogConfig類中的log()方法中，創(chuàng)建LogEvent對象，調(diào)用processLogEvent()方法將LogEvent對象傳入對應(yīng)的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()方法，最后調(diào)用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.”，它的作用是將日志事件傳遞到指定目標(biāo)。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隊列，隊列默認(rèn)大小為1024，一個單獨的線程類AsyncThread，還有它引用的Appender數(shù)組。

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

首先來看AsyncAppender是如何將日志事件存入隊列的，下面是AsyncAppender類中的append(LogEvent logEvent)方法，可以看到在appender方法中調(diào)用了私有方法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)) {//?省略隊列阻塞等待相關(guān)處理}?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。

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

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

log4j2.xml配置如下：

3、AsyncLogger 異步方式

AsyncLogger的異步記錄器是Log4j2的一個新特性，可以通過在單獨的線程中執(zhí)行I/O操作來提高應(yīng)用程序的性能。其內(nèi)部使用了disruptor框架，其底層數(shù)據(jù)結(jié)構(gòu)為無鎖環(huán)形隊列，每次日志信息保存在隊列中，另一個線程將隊列中日志寫入文件。

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.

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

disruptor框架的底層結(jié)構(gòu)是環(huán)形緩沖區(qū)RingBuffer，當(dāng)日志到達(dá)后，AsyncLogger的logMessage()方法會將日志信息轉(zhuǎn)換為RingBufferLogEventTranslator對象，然后調(diào)用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中讀取存入的事件，回調(diào)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）全異步方式，需要設(shè)置系統(tǒng)屬性，指定log4j2.contextSelector值為org.apache.logging.log4j.core.async.AsyncLoggerContextSelector，配置文件中使用<Logger>或<Root>標(biāo)簽

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

混合同步異步方式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>

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

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

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

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

接下來我們就要通過測試數(shù)據(jù)來尋找答案。

實測數(shù)據(jù)對比

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

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

JDK：1.8
Spring Boot : 2.1.3.RELEASE
Log4j2 ：2.13.1
Disruptor：3.4.2

1、單個Appender

壓測過程中，初始CPU差別不大，400個并發(fā)用戶數(shù)使機器CPU使用率達(dá)到100%。

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

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

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

2、3個Appender

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

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

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

3、6個Appender

結(jié)合前面幾個圖，可以看出，當(dāng)有6個Appender的時候，AsyncAppender的線程數(shù)比單個Appender增加了5個，使用AsyncLogger的系統(tǒng)性能和使用AsyncAppender的系統(tǒng)性能有了明顯的優(yōu)勢，也就是說當(dāng)Appender越多時，AsyncLogger的性能優(yōu)勢在三種日志記錄方式中表現(xiàn)的越明顯。

4、immediateFlush

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

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.

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

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

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

小結(jié)

1、在線程使用方面，log4j2的同步方式使用和業(yè)務(wù)邏輯相同的線程處理日志輸出；AsyncAppender內(nèi)部使用ArrayBlockingQueue隊列，對于每一個AsyncAppender都會創(chuàng)建一個線程處理日志輸出；AsyncLogger內(nèi)部使用了disruptor框架，其底層數(shù)據(jù)結(jié)構(gòu)為無鎖環(huán)形隊列，使用一個單獨線程處理日志輸出。

2、在日志內(nèi)容較多，打印日志頻繁的情況下，兩種異步日志記錄方式會優(yōu)于同步方式。

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

總結(jié)

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

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。

上一篇：微服务平台改造落地解决方案设计
下一篇：从0到70%：Chrome上位揭秘！