文章鏈接: https://pengcheng.site/2019/11/17/log4j-he-log4j2-zai-springboot-zhong-de-xing-neng-dui-bi/
前言
在 java 項目中最常用的三大日志框架是logback，log4j，log4j2。其中logback是 springboot 的默認框架。由於歷史原因，我手上有個springboot項目的日志框架是用的log4j。在對某個接口進行壓測和性能優化的時候發現，打印同步日志會導致接口的性能縮水，所以當時直接把性能要求高的接口的日志關閉掉了。隨着系統的逐漸復雜，重要性越來越高，定位問題的難度越來越大，我逐漸感覺到日志的的重要性。所以優化日志勢在必行。
我是從兩個方面來考慮優化日志這個問題的。
- 更換性能更高的日志框架；
- 使用異步日志或者延時刷盤的日志配置。
對第一個問題，很容易就可以Google到，目前性能表現最好的日志框架是log4j2，所以直接把日志框架替換成log4j2就可以了。
對於第二個問題，因為當前日志是同步的，需要把“打印日志”這個操作完成之后才會運行接下來的業務代碼，而“打印日志”通常是要輸出到控制台或者文件中的，IO開銷很大，如果把這個過程變成異步的應該能從一定程度上提高性能表現。
不知道在哪聽到的兩句話，想在這里分享一下：
- 沒有日志的系統就像在裸奔
- 沒有uid的日志是沒有靈魂的
PS：這里沒有uid的本來是指是調用方的id，更一般的說法就是不能定位問題的日志是沒有存在價值的。
環境
- springboot 2.1.5
- java 8
- MacBook Pro 2017
log4j日志
log4j 在 springboot 中的配置
在 springboot 中使用 log4j 需要引入其依賴並把 springboot 自帶的日志框架 logback 排除掉:
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-log4j</artifactId>
<version>1.3.8.RELEASE</version>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter</artifactId>
<exclusions>
<exclusion>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-logging</artifactId>
</exclusion>
</exclusions>
</dependency>
然后編寫配置文件log4j.properties:
log4j.rootLogger=INFO,stdout,file
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} [%p] %c:[%L] %m%n
log4j.appender.file=org.apache.log4j.DailyRollingFileAppender
log4j.appender.file.File=logs/seller_penalty_api_server.log
log4j.appender.file.Append=true
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} [%p] %c:[%L] %m%n
性能測試
知己知彼，百戰不殆。
要對比性能，首先就要知道原來的log4j框架的性能表現如何。
這里我使用了一種簡單的方式來進行對比。在 springboot 中實現兩個簡單的接口，一個打印一行日志，一個不打印日志，然后用wrk工具對接口進行壓測，看兩個接口能夠達到的QPS分別是多少。
// 不打印日志
@GetMapping("/ping")
public String ping() {
return "pang";
}
// 打印日志
@GetMapping("pingLog")
public String pingWithLog() {
log.info("calling /pingLog");
return "pangLog";
}
壓測配置如下，分別對兩個接口進行多次壓測，取三次作為采樣結果。
wrk -t10 -c250 -d30s http://localhost:8080/ping
| 采樣次數 | 1 | 2 | 3 |
|---|---|---|---|
| 不打印日志 | 21937.40 | 23570.31 | 22950.31 |
| 打印日志 | 7825.40 | 7848.33 | 7788.54 |
可以看到兩種情況基本上有將近三倍的差距。我是用nohup后台運行的，如果直接使用java -jar運行，日志輸出到文件的同時還會輸出到控制台，這種情況QPS將進一步降低，大概在5k+左右。這也正是我們最開始為了接口性能選擇關閉日志的原因
log4j2
引入log4j2（同log4j一樣，要排除 springboot 自帶的日志框架）：
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>
<!-- 增加識別yaml格式依賴，加上這個才能辨認到log4j2.yml文件 -->
<dependency>
<groupId>com.fasterxml.jackson.dataformat</groupId>
<artifactId>jackson-dataformat-yaml</artifactId>
</dependency>
然后在src/main/resources/路徑中編寫log4j2的配置文件。默認配置文件名是log4j2，支持xml、properties、json、yaml多種文件格式，這里我選了yml，所以需要額外引入jackson-dataformat-yaml的包。
Configuration:
status: debug
appenders: # 包含控制台和文件兩個appender
Console:
name: LogToConsole
PatternLayout:
Pattern: "%d{yyyy-MM-dd HH:mm:ss} [%p] %c:[%L] %m%n"
RollingFile:
- name: LogToRollingFile
fileName: logs/seller_penalty_api_server.log
filePattern: "logs/seller_penalty_api_server.log.%d{yyyy-MM-dd}.gz" # 帶有后綴名會自動壓縮
PatternLayout:
pattern: "%d{yyyy-MM-dd HH:mm:ss} [%p] %c:[%L] %m%n"
Policies:
TimeBasedTriggeringPolicy: # 基於時間的trigger，每天一個文件
interval: 1
Loggers:
logger:
- name: io.shopee.bigdata.penalty.server
level: debug
additivity: false
AppenderRef:
- ref: LogToConsole
- ref: LogToRollingFile
Root:
level: error
AppenderRef:
ref: LogToConsole
使用log4j2之后，使用wrk和同樣的參數壓測（關掉控制台輸入），三次測試的QPS分別是：
| 采樣次 | 1 | 2 | 3 |
|---|---|---|---|
| QPS | 13992.50 | 15562.27 | 15161.16 |
可以看到在這個簡單的場景下，性能幾乎是log4j的2到3倍之多！所以很明顯，首先替換日至框架是一個明智的選擇。
log4j2 異步日志
到目前為止，上述的測試都是針對同步日志進行的測試。在確定了log4j2作為日志框架之后，我想看一下，使用異步日志能不能進一步提高性能表現。
AsyncAppender 和 Asynchronous Loggers
在log4j2中異步日志有兩種實現AsyncAppender 和 Asynchronous Loggers
前者是 log4j2 最開始的異步日志實現，它把其他 Appender 作為輸入，然后把產生 logEvent輸出到默認的容器ArrayBlockingQueue中，然后使用另外一個線程中來輸出日志以實現異步。但是官方文檔也指出：
在這種多線程應用的實踐中需要主要：阻塞隊列很容易發生鎖爭用，測試表明當大量線程並發寫日志的時候，性能甚至會變得更糟糕。所以應該考慮使用無鎖的Asyn Loggers進行優化。
上述的Asyn Loggers是log42 團隊后來才加入的異步實現，連官方文檔都推薦它了，那還有什么好猶豫的呢。它需要引入一個額外的依賴：
<dependency>
<groupId>com.lmax</groupId>
<artifactId>disruptor</artifactId>
<version>3.4.2</version>
</dependency>
Disruptor 通過CAS而不是鎖實現多生產者、多消費者對RingBuffer的並發訪問，實現高吞吐和高性能。
它們兩者的具體區別可以參考參考資料2
全異步和混合異步
Log4j2的異步日志的使用又可以分為全異步和混合異步，所謂全異步就是所有的日志都以異步方式輸出；混合異步就是只有指定的代碼文件用異步方式輸出，其他日志使用同步方式輸出；前者能夠獲得更高的性能，也是官方推薦的方式，后者具有更好的靈活性，可以進行針對性配置。
本文中我們直接使用全異步日志。
在springboot中開啟全異步的方式很簡單，只需要在配置文件中加如下配置（yml）：
log4j2:
contextSelector: org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
或者在用java -jar 啟動的時候加入系統參數：
-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
應用啟動之后按照上述的方法測試接口性能：
| 采樣次 | 1 | 2 | 3 |
|---|---|---|---|
| QPS | 16238.76 | 16006.78 | 16322.12 |
可以看到把日志從同步改成異步之后，性能有一定提升，但是並沒有想象中那么大。
總結
- 同步日志和業務邏輯在同一個線程中，當日志輸出完畢才能執行接下來的代碼，涉及到IO，非常影響性能；
log4j2在本文的簡單場景中性能要遠遠高於log4j，這次替換是值得的；log4j2異步日志應該使用Asynchronous Loggers而不是AsyncAppender- 本次測試是基於一個很簡單的場景，在官方文檔中，異步日志的性能要遠遠超過同步日志的，但是在本次測試中並沒有體現出來；日志在 springboot 中的性能可能受多個方面的影響，比如每個調用鏈中日志的條數、springboot本身的配置，日志的level、硬件環境等。
- 項目代碼見Github
彩蛋1-性能測試需要注意的點
關於性能測試，在 log4j2 的官方文檔中提到的幾點我覺得是比較通用的:
- 獲取性能的采樣結果之前需要 warm up the JVM；
- 重復熱身多次，然后等待IO線程趕上並釋放緩沖區;
- 測試的時候重復多次取平均數。
總結一下就是系統剛啟動的一段時間的測試數據不能作為參考，需要壓測一段時間，取穩定之后的結果。就像運動前的熱身一樣，不光JVM，各種線程池或連接池都需要一段時間的請求才能啟動起來進入正常工作狀態。
彩蛋2-springboot 中多環境日志配置
在springboot中我們通常針對dev，test，live等多種環境會有多套配置文件，比如application-dev.yml,application-test.yml, application-live.yml。然后可以在啟動的時候可以通過在全局配置文件application.yml指定某個配置文件來啟用配置：
sping:
profiles:
active: live
日志同樣有這樣的需求，不同環境使用不同的日志配置，比如dev或test環境需要開啟的log level為DEBUG，而在live環境中卻不需要。這種時候我們只需要寫多套日志配置，比如log4j2-dev.yml，log4j2-test.yml，log4j2-live.yml，然后在其對應的配置文件中啟用日志配置就可以了：
logging:
config: classpath:log4j2-dev.yml
參考資料
- Spring Boot Log4j 2 example
- Log4j2中的同步日志與異步日志
- Difference between Asynclogger and AsyncAppender in Log4j2
- https://www.callicoder.com/spring-boot-log4j-2-example/
原文發表於：https://pengcheng.site/2019/10/28/springboot-zi-dong-pei-zhi-qian-xi/