Log4j2中的同步日誌與異步日誌
1.背景
Log4j 2中記錄日誌的方式有同步日誌和異步日誌兩種方式，其中異步日誌又可分為使用AsyncAppender和使用AsyncLogger兩種方式。
2.Log4j2中的同步日誌
所謂同步日誌，即當輸出日誌時，必須等待日誌輸出語句執行完畢後，才能執行後面的業務邏輯語句。
下面通過一個例子來了解Log4j2中的同步日誌，並借此來探究整個日誌輸出過程。
log4j2.xml配置如下：
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug" name="MyApp" packages="">
<!--全局Filter-->
<ThresholdFilter level="ALL"/>
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
</Console>
<RollingFile name="RollingFile" fileName="logs/app.log"
filePattern="logs/app-%d{yyyy-MM-dd HH}.log">
<!--Appender的Filter-->
<ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
<PatternLayout>
<Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
</PatternLayout>
<Policies>
<SizeBasedTriggeringPolicy size="500MB"/>
</Policies>
</RollingFile>
</Appenders>
<Loggers>
<Logger name="com.meituan.Main" level="trace" additivity="false">
<!--Logger的Filter-->
<ThresholdFilter level="debug"/>
<appender-ref ref="RollingFile"/>
</Logger>
<Root level="debug">
<AppenderRef ref="Console"/>
</Root>
</Loggers>
</Configuration>
|
java代碼如下：
package com.meituan;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
public class Main {
public static void main(String args[]) {
Logger logger = LogManager.getLogger(Main.class);
Person person = new Person("Li", "lei");
logger.info("hello, {}", person);
}
private static class Person {
private String firstName;
private String lastName;
public Person(String firstName, String lastName) {
this.firstName = firstName;
this.lastName = lastName;
}
public String toString() {
return "Person[" + firstName + "," + lastName + "]";
}
}
}
|
使用以上的配置，當我們運行程序後，以下log將被添加到logs/app.log中。
2017-09-13 19:41:00,889 INFO c.m.Main [main] hello, Person[Li,lei]
|
logger.info運行時到底發生了什麽？日誌信息是如何輸出到app.log中的？
draw.io evaluation version logger.info("hello,{}", person) 全局Filter進行Level過濾 生成日誌輸出內容 Message Logger自身Level過濾 生成LogEvent Logger配置的Filter進行 Level過濾 Appender配置的Filter進行 Level過濾 是否rollover PatternLayout 格式化LogEvent OutputStream 輸出到app.log 2017-09-13 19:41:00,889 INFO c.m.Main [main] hello, Person[Li,lei] Appender Logger LogEvent main線程
Log4j2中日誌輸出的詳細過程如下：
1.首先使用全局Filter對日誌事件進行過濾。
Log4j2中的日誌Level分為8個級別，優先級從高到低依次為OFF、FATAL、ERROR、WARN、INFO、DEBUG、TRACE、 ALL。
全局Filter的Level為ALL，表示允許輸出所有級別的日誌。logger.info()請求輸出INFO級別的日誌，通過。
2.使用Logger的Level對日誌事件進行過濾。
Logger的Level為TRACE，表示允許輸出TRACE級別及以上級別的日誌。logger.info()請求輸出INFO級別的日誌，通過。
3.生成日誌輸出內容Message。
使用占位符的方式輸出日誌，輸出語句為logger.info("increase {} from {} to {}", arg1, arg2, arg3)的形式，最終輸出時{}占位符處的內容將用arg1,arg2,arg3的字符串填充。
log4j2用Object[]保存參數信息，在這一階段會將Object[]轉換為String[]，生成含有輸出模式串"increase {} from {} to {}"和參數數組String[]的Message，為後續日誌格式化輸出做準備。
4.生成LogEvent。
LogEvent中含有loggerName（日誌的輸出者），level（日誌級別），timeMillis（日誌的輸出時間），message（日誌輸出內容），threadName（線程名稱）等信息。
在上述程序中，生成的LogEvent的屬性值為loggerName=com.meituan.Main，Level=INFO，timeMillis=1505659461759，message為步驟3中創建的Message，threadNama=main。
5.使用Logger配置的Filter對日誌事件進行過濾。
Logger配置的Filter的Level為DEBUG，表示允許輸出DEBUG及以上級別的日誌。logger.info()請求輸出INFO級別的日誌，通過。
6.使用Logger對應的Appender配置的Filter對日誌事件進行過濾。
Appender配置的Filter配置的INFO級別日誌onMatch=ACCEPT，表示允許輸出INFO級別的日誌。logger.info()請求輸出INFO級別的日誌，通過。
7.判斷是否需要觸發rollover。
此步驟不是日誌輸出的必須步驟，如配置的Appender為無需進行rollover的Appender，則無此步驟。
因為使用RollingFileAppender，且配置了基於文件大小的rollover觸發策略，在此階段會判斷是否需要觸發rollover。判斷方式為當前的文件大小是否達到了指定的size，如果達到了，觸發rollover操作。關於Log4j2中的RollingFileAppender的rollover，可參見Log4j2中RollingFile的文件滾動更新機制。
8.PatternLayout對LogEvent進行格式化，生成可輸出的字符串。
上述log4j2.xml文件中配置的Pattern及各個參數的意義如下：
<Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
|
| 參數 | 意義 |
|---|---|
%d |
日期格式，默認形式為2012-11-02 14:34:02,781 |
%p |
日誌級別 |
%c{1.}
|
%c表示Logger名字，{1.}表示精確度。若Logger名字為org.apache.commons.Foo，則輸出o.a.c.Foo。 |
%t |
處理LogEvent的線程的名字 |
%m |
日誌內容 |
%n |
行分隔符。"\n"或"\r\n"。 |
在此步驟，PatternLayout將根據Pattern的模式，利用各種Converter對LogEvent的相關信息進行轉換，最終拼接成可輸出的日誌字符串。
如DatePatternConverter對LogEvent的日誌輸出時間進行格式化轉換；LevelPatternConverter對LogEvent的日誌級別信息進行格式化轉換；LoggerPatternConverter對LogEvent的Logger的名字進行格式化轉換；MessagePatternConverter對LogEvent的日誌輸出內容進行格式化轉換等。
經各種Converter轉換後，LogEvent的信息被格式化為指定格式的字符串。
9.使用OutputStream，將日誌輸出到文件。
將日誌字符串序列化為字節數組，使用字節流OutoutStream將日誌輸出到文件中。如果配置了immediateFlush為true，打開app.log就可觀察到輸出的日誌了。
3.Log4j2中的異步日誌
使用log4j2的同步日誌進行日誌輸出，日誌輸出語句與程序的業務邏輯語句將在同一個線程運行，如上面的例子，打印的日誌中顯示的線程名稱為main，與業務邏輯語句在同一個線程中（此句有誤，LogEvent中的線程名稱不是輸出LogEvent的線程，是生成LogEvent的線程，輸出LogEvent的線程和生成LogEvent可能不是一個線程！）。
而使用異步日誌進行輸出時，日誌輸出語句與業務邏輯語句並不是在同一個線程中運行，而是有專門的線程用於進行日誌輸出操作，處理業務邏輯的主線程不用等待即可執行後續業務邏輯。
Log4j2中的異步日誌實現方式有AsyncAppender和AsyncLogger兩種。
其中，AsyncAppender采用了ArrayBlockingQueue來保存需要異步輸出的日誌事件；AsyncLogger則使用了Disruptor框架來實現高吞吐。
3.1 AsyncAppender
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn">
<Appenders>
<RollingFile name="MyFile" fileName="logs/app.log">
<PatternLayout>
<Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
</PatternLayout>
<SizeBasedTriggeringPolicy size="500MB"/>
</RollingFile>
<Async name="Async">
<AppenderRef ref="MyFile"/>
</Async>
</Appenders>
<Loggers>
<Root level="error">
<AppenderRef ref="Async"/>
</Root>
</Loggers>
</Configuration>
|
上面就是一個使用AsyncAppender的典型配置，配置AsyncAppender後，日誌事件寫入文件的操作將在單獨的線程中執行。
AsyncAppender的常用參數
| 參數名 | 類型 | 說明 |
|---|---|---|
| name | String | Async Appender的名字。 |
| AppenderRef | String |
異步調用的Appender的名字，可以配置多個。 |
| blocking | boolean |
默認為true。如果為true，appender將一直等待直到queue中有空閑；如果為false，當隊列滿的時候，日誌事件將被丟棄。(如果配置了error appender，要丟棄的日誌事件將由error appender處理) |
| bufferSize | integer |
隊列中可存儲的日誌事件的最大數量，默認為128。(源碼中為128，Log4j2官網為1024，官網信息有誤) |
關於AsyncAppender的其他參數，可參考Log4j2對AsyncAppender的詳細介紹。
每個Async Appender，內部維護了一個ArrayBlockingQueue，並將創建一個線程用於輸出日誌事件，如果配置了多個AppenderRef，將分別使用對應的Appender進行日誌輸出。
3.2 AsyncLogger
Log4j2中的AsyncLogger的內部使用了Disruptor框架。
Disruptor簡介
Disruptor是英國外匯交易公司LMAX開發的一個高性能隊列，基於Disruptor開發的系統單線程能支撐每秒600萬訂單。
目前，包括Apache Strom、Log4j2在內的很多知名項目都應用了Disruptor來獲取高性能。
Disruptor框架內部核心數據結構為RingBuffer，其為無鎖環形隊列。
單線程每秒能夠處理600萬訂單，Disruptor為什麽這麽快？
a.lock-free-使用了CAS來實現線程安全
ArrayBlockingQueue使用鎖實現並發控制，當get或put時，當前訪問線程將上鎖，當多生產者、多消費者的大量並發情形下，由於鎖競爭、線程切換等，會有性能損失。
Disruptor通過CAS實現多生產者、多消費者對RingBuffer的並發訪問。CAS相當於樂觀鎖，其性能優於Lock的性能。
b.使用緩存行填充解決偽共享問題
計算機體系結構中，內存的訪問速度遠遠低於CPU的運行速度，在內存和CPU之間，加入Cache，CPU首先訪問Cache中的數據，CaChe未命中，才訪問內存中的數據。
偽共享：Cache是以緩存行（cache line）為單位存儲的，當多個線程修改互相獨立的變量時，如果這些變量共享同一個緩存行，就會無意中影響彼此的性能。
關於偽共享的深度分析，可參考《偽共享，並發編程的性能殺手》這篇文章。
AsyncLogger
Log4j2異步日誌如何進行日誌輸出，我們同樣從一個例子出發來探究Log4j2的異步日誌。
log4j2.xml配置如下：
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug" name="MyApp" packages="">
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
</Console>
<RollingFile name="RollingFile" fileName="logs/app.log"
filePattern="logs/app-%d{yyyy-MM-dd HH}.log">
<PatternLayout>
<Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
</PatternLayout>
<Policies>
<SizeBasedTriggeringPolicy size="500MB"/>
</Policies>
</RollingFile>
<RollingFile name="RollingFile2" fileName="logs/app2.log"
filePattern="logs/app2-%d{yyyy-MM-dd HH}.log">
<PatternLayout>
<Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
</PatternLayout>
<Policies>
<SizeBasedTriggeringPolicy size="500MB"/>
</Policies>
</RollingFile>
</Appenders>
<Loggers>
<AsyncLogger name="com.meituan.Main" level="trace" additivity="false">
<appender-ref ref="RollingFile"/>
</AsyncLogger>
<AsyncLogger name="RollingFile2" level="trace" additivity="false">
<appender-ref ref="RollingFile2"/>
</AsyncLogger>
<Root level="debug">
<AppenderRef ref="Console"/>
<AppenderRef ref="RollingFile"/>
</Root>
</Loggers>
</Configuration>
|
java代碼如下：
public class Main {
public static void main(String args[]) {
Logger logger = LogManager.getLogger(Main.class);
Logger logger2 = LogManager.getLogger("RollingFile2");
Person person = new Person("Li", "lei");
logger.info("hello, {}", person);
logger2.info("good bye, {}", person);
}
|
上述log4j2.xml中配置了兩個AsyncLogger，名字分別為com.meituan.Main和RollingFile2。
並且，在main方法中分別使用兩個logger來輸出兩條日誌。
在加載log4j2.xml的啟動階段，如果檢測到配置了AsyncRoot或AsyncLogger，將啟動一個disruptor實例。
draw.io evaluation version LogEvent LogEvent logger.info Logger Logger logger.info main線程 logger=LogManager.get(XxxService.class) logger=LogManager.get(XxxController.class) RingBuffer Appender LogEvent EventProcessor線程 Appender LogEvent
上述程序中，main線程作為生產者，EventProcessor線程作為消費者。
生產者生產消息
當運行到類似於logger.info、logger.debug的輸出語句時，將生成的LogEvent放入RingBuffer中。
消費者消費消息
如果RingBuffer中有LogEvent需要處理，EventProcessor線程從RingBuffer中取出LogEvent，調用Logger相關聯的Appender輸出LogEvent（具體輸出過程與同步過程相同，同樣需要過濾器過濾、PatternLayout格式化等步驟）。
如果RingBuffer中沒有LogEvent需要處理，EventProcessor線程將處於等待阻塞狀態（默認策略）。
需要註意的是，雖然在log4j2.xml中配置了多個AsyncLogger，但是並不是每個AsyncLogger對應著一個處理線程，而是僅僅有一個EventProcessor線程進行日誌的異步處理。
4.總結
| 日誌輸出方式 | |
|---|---|
| sync | 同步打印日誌，日誌輸出與業務邏輯在同一線程內，當日誌輸出完畢，才能進行後續業務邏輯操作 |
| Async Appender | 異步打印日誌，內部采用ArrayBlockingQueue，對每個AsyncAppender創建一個線程用於處理日誌輸出。 |
| Async Logger | 異步打印日誌，采用了高性能並發框架Disruptor，創建一個線程用於處理日誌輸出。 |
Log4j2中的同步日誌與異步日誌