1 問題回顧

1.1 問題描述

在專案的效能測試中，相關的介面的隨著並行數增加，介面的響應時間變長，介面吞吐不再增長，應用的CPU使用率較高。

1.2 分析思路

誰導致的CPU較高，阻塞介面TPS的增長？介面的響應時間的呼叫鏈分佈是什麼樣的，有沒有慢的點？

1）使用火焰圖分析應用的CPU如下，其中log4j2紀錄檔佔了40%左右CPU，初步懷疑是log4j2的問題。

2）呼叫鏈的分析

通過pfinder檢視呼叫鏈發現，介面總耗時78ms，沒有明顯慢的呼叫方法和慢sql等，先排除介面的本身的程式碼問題。

1.3 初步結論

log4j2的問題，需詳細分析紀錄檔的相關設定log4j2.xml。

上面可以看到紀錄檔中Loggers節點下的節點以及節點都是列印的同步紀錄檔。同步紀錄檔是程式的業務邏輯和紀錄檔輸出語句均在一個執行緒執行，當紀錄檔較多，在一定程度上阻塞了業務的執行效率。改成非同步紀錄檔試一下：

改成非同步紀錄檔設定：使用AsyncLogger

1.4 迴歸驗證

同步紀錄檔改成非同步紀錄檔後。同樣10並行，介面的TP99由 51ms 降到 23ms，介面的吞吐TPS由 493提高到 1078，應用的CPU由 82%降到 57%。

完美end。問題解決了，但是log4j2的紀錄檔我們還是要詳細研究學習一下。

1.5 結論

log4j2使用非同步紀錄檔將大幅提升效能，減少對應用本身的影響。
從根本上減少不必要紀錄檔的輸出。

但是log4j2非同步紀錄檔是怎麼實現的和同步紀錄檔有什麼區別？為什麼非同步紀錄檔的的效率更高？引發我去學習一下log4j2的相關知識，下面和大家分享一下：

2 log4j2紀錄檔

2.1 log4j2的優勢

log4j2是log4j 1.x 的升級版，參考了logback的一些優秀的設計，並且修復了一些問題，因此帶來了一些重大的提升，主要有：

例外處理，在logback中，Appender中的異常不會被應用感知到，但是在log4j2中，提供了一些例外處理機制。
效能提升， log4j2相較於log4j 1和logback都具有很明顯的效能提升，後面會有官方測試的資料。
自動過載設定，參考了logback的設計，當然會提供自動重新整理引數設定，最實用的就是我們在生產上可以動態的修改紀錄檔的級別而不需要重啟應用——那對監控來說，是非常敏感的。
無垃圾機制，log4j2在大部分情況下，都可以使用其設計的一套無垃圾機制，避免頻繁的紀錄檔收集導致的jvm gc。

2.2 Log4J2紀錄檔分類

Log4j2中記錄紀錄檔的方式有同步紀錄檔和非同步紀錄檔兩種方式，其中非同步紀錄檔又可分為使用AsyncAppender和使用AsyncLogger兩種方式。使用LOG4J2有三種紀錄檔模式,全非同步紀錄檔,混合模式,同步紀錄檔,效能從高到底,執行緒越多效率越高,也可以避免紀錄檔卡死執行緒情況發生。

同步和非同步紀錄檔的效能對比：

2.3 同步紀錄檔

使用log4j2的同步紀錄檔進行紀錄檔輸出，紀錄檔輸出語句與程式的業務邏輯語句將在同一個執行緒執行，即當輸出紀錄檔時，必須等待紀錄檔輸出語句執行完畢後，才能執行後面的業務邏輯語句。

2.4 非同步紀錄檔

而使用非同步紀錄檔進行輸出時，紀錄檔輸出語句與業務邏輯語句並不是在同一個執行緒中執行，而是有專門的執行緒用於進行紀錄檔輸出操作，處理業務邏輯的主執行緒不用等待即可執行後續業務邏輯。

log4j2最大的特點就是非同步紀錄檔，其效能的提升主要也是從非同步紀錄檔中受益，我們來看看如何使用log4j2的非同步紀錄檔

Log4j2中的非同步紀錄檔實現方式有AsyncAppender和AsyncLogger兩種。
其中：

AsyncAppender採用了ArrayBlockingQueue來儲存需要非同步輸出的紀錄檔事件；
AsyncLogger則使用了Disruptor框架來實現高吞吐。

注意這是兩種不同的實現方式，在設計和原始碼上都是不同的體現。

2.4.1 AsyncAppender

AsyncAppender是通過參照別的Appender來實現的，當有紀錄檔事件到達時，會開啟另外一個執行緒來處理它們。需要注意的是，如果在Appender的時候出現異常，對應用來說是無法感知的。 AsyncAppender應該在它參照的Appender之後設定，預設使用 java.util.concurrent.ArrayBlockingQueue實現而不需要其它外部的類庫。當使用此Appender的時候，在多執行緒的環境下需要注意，阻塞佇列容易受到鎖爭用的影響，這可能會對效能產生影響。

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn">
 <Appenders>
 <!--正常的Appender設定，此處設定的RollingFile會在下面AsyncAppender被通過name參照-->
 <RollingFile name="RollingFileError" fileName="${Log_Home}/error.${date:yyyy-MM-dd}.log" immediateFlush="true"
filePattern="${Log_Home}/$${date:yyyy-MM}/error-%d{MM-dd-yyyy}-%i.log.gz">
     <PatternLayout pattern="%d{yyyy-MM-dd 'at' HH:mm:ss z} %-5level %logger{36} : %msg%xEx%n"/>
       <ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY"/>
       <Policies>
        <TimeBasedTriggeringPolicy modulate="true" interval="1"/>
        <SizeBasedTriggeringPolicy size="10MB"/>
        </Policies>
 </RollingFile>
 <!--一個Appender設定完畢-->
 <!--非同步AsyncAppender進行設定直接參照上面的RollingFile的name-->
 <Async name="Async">
        <AppenderRef ref="RollingFileError"/>
 </Async>
 <!--非同步AsyncAppender設定完畢，需要幾個設定幾個-->
 </Appenders>

 <Loggers>
         <Root level="error">
          <!--此處如果參照非同步AsyncAppender的name就是非同步輸出紀錄檔-->
         <!--此處如果參照Appenders標籤中RollingFile的name就是同步輸出紀錄檔-->
          <AppenderRef ref="Async"/>
</Root>
 </Loggers>
</Configuration>

2.4.2 AsyncLogger

AsyncLogger才是log4j2 的重頭戲，也是官方推薦的非同步方式。它可以使得呼叫Logger.log返回的更快。Log4j2中的AsyncLogger的內部使用了Disruptor框架。

Disruptor簡介
Disruptor是英國外匯交易公司LMAX開發的一個高效能佇列，基於Disruptor開發的系統單執行緒能支撐每秒600萬訂單。
目前，包括Apache Strom、Log4j2在內的很多知名專案都應用了Disruptor來獲取高效能。
Disruptor框架內部核心資料結構為RingBuffer，其為無鎖環形佇列。

Disruptor為什麼這麼快？

lock-free-使用了CAS來實現執行緒安全
使用快取行填充解決偽共用問題

非同步紀錄檔可以有兩種選擇：全域性非同步和混合非同步。

1）全域性非同步

全域性非同步就是，所有的紀錄檔都非同步的記錄，在組態檔上不用做任何改動，只需要在jvm啟動的時候增加一個引數；這是最簡單的設定，並提供最佳效能。
然後在src/java/resources目錄新增log4j2.component.properties組態檔

設定非同步紀錄檔系統屬性

log4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

2）混合非同步

混合非同步就是，你可以在應用中同時使用同步紀錄檔和非同步紀錄檔，這使得紀錄檔的設定方式更加靈活。因為Log4j檔案中也說了，雖然Log4j2提供以一套例外處理機制，可以覆蓋大部分的狀態，但是還是會有一小部分的特殊情況是無法完全處理的，比如我們如果是記錄審計紀錄檔，那麼官方就推薦使用同步紀錄檔的方式，而對於其他的一些僅僅是記錄一個程式紀錄檔的地方，使用非同步紀錄檔將大幅提升效能，減少對應用本身的影響。混合非同步的方式需要通過修改組態檔來實現，使用AsyncLogger標記設定。

第一步：pom中新增相關jar包

<dependency>
  <groupId>com.lmax</groupId>
  <artifactId>disruptor</artifactId>
  <version>3.4.2</version>
</dependency>

第二步：log4j2.xml同步紀錄檔和非同步紀錄檔（設定AsyncLogger）混合設定的例子如下：

<?xml version="1.0" encoding="UTF-8"?>
<!--紀錄檔級別以及優先順序排序: OFF > FATAL > ERROR > WARN > INFO > DEBUG > TRACE > ALL -->
 <!--status="WARN" :用於設定log4j2自身內部紀錄檔的資訊輸出級別，預設是OFF-->
 <!--monitorInterval="30" :間隔秒數,自動檢測組態檔的變更和重新設定本身-->
<configuration status="WARN" monitorInterval="30">
   <Properties>
       <!--1、自定義一些常數，之後使用${變數名}參照-->
       <Property name="logFilePath">log</Property>
       <Property name="logFileName">test.log</Property>
   </Properties>
   <!--2、appenders:定義輸出內容,輸出格式,輸出方式,紀錄檔儲存策略等,常用其下三種標籤[console,File,RollingFile]-->
   <!--Appenders中設定紀錄檔輸出的目的地
           console只的是控制檯 system.out.println
           rollingFile 只的是檔案大小達到指定尺寸的時候產生一個新的檔案-->
   <appenders>
       <!--console :控制檯輸出的設定-->
       <console name="Console" target="SYSTEM_OUT">
           <!--PatternLayout :輸出紀錄檔的格式,LOG4J2定義了輸出程式碼,詳見第二部分 %p 輸出優先順序，即DEBUG，INFO，WARN，ERROR，FATAL-->
           <PatternLayout pattern="[%d{HH:mm:ss:SSS}] [%p] - %l - %m%n"/>
       </console>
       <!--File :同步輸出紀錄檔到本地檔案-->
       <!--append="false" :根據其下紀錄檔策略,每次清空檔案重新輸入紀錄檔,可用於測試-->
       <File name="log" fileName="${logFilePath}/${logFileName}" append="false">
           <!-- 格式化輸出：
           %d表示日期，%thread表示執行緒名，
           %-5level：級別從左顯示5個字元寬度
           %thred: 輸出產生該紀錄檔事件的執行緒名
           %class：是輸出的類
           %L: 輸出程式碼中的行號
           %M：方法名
           %msg：紀錄檔訊息，
           %n是換行符
           %c: 輸出紀錄檔資訊所屬的類目，通常就是所在類的全名 
           %t: 輸出產生該紀錄檔事件的執行緒名 
           %l: 輸出紀錄檔事件的發生位置，相當於%C.%M(%F:%L)的組合,包括類目名、發生的執行緒，以及在程式碼中的行數。舉例：Testlog4.main(TestLog4.Java:10) 
           %p: 輸出紀錄檔資訊優先順序，即DEBUG，INFO，WARN，ERROR，FATAL,

           2020.02.06 at 11:19:54 CST INFOcom.example.redistest.controller.PersonController 40 setPerson - 新增成功1條資料
           -->
           <!-- %class{36} 表示 class 名字最長36個字元 -->
           <PatternLayout pattern="%d{HH:mm:ss.SSS} %-5level %class{36} %L %M - %msg%xEx%n"/>
       </File>
       <!--
       關鍵點在於 filePattern後的日期格式，以及TimeBasedTriggeringPolicy的interval，日期格式精確到哪一位，interval也精確到哪一個單位.
       1） TimeBasedTriggeringPolicy需要和filePattern配套使用，由於filePattern設定的時間最小粒度如果設定是dd天，所以表示每一天新建一個檔案儲存紀錄檔。
       2） SizeBasedTriggeringPolicy表示當檔案大小大於指定size時，生成新的檔案儲存紀錄檔。與%i配合使用-->

       <RollingFile name="RollingFileInfo" fileName="${sys:user.home}/logs/info.log"
                    filePattern="${sys:user.home}/logs/$${date:yyyy-MM}/info-%d{yyyy-MM-dd}-%i.log">
           <!--ThresholdFilter :紀錄檔輸出過濾-->
           <!--level="info" :紀錄檔級別,onMatch="ACCEPT" :級別在info之上則接受,onMismatch="DENY" :級別在info之下則拒絕-->
           <ThresholdFilter level="info" onMatch="ACCEPT" onMismatch="DENY"/>
           <PatternLayout pattern="[%d{HH:mm:ss:SSS}] [%p] - %l - %m%n"/>
           <!-- Policies :紀錄檔卷動策略-->
           <Policies>
               <!-- TimeBasedTriggeringPolicy :時間捲動策略,預設0點小時產生新的檔案,interval="6" : 自定義檔案卷動時間間隔,每隔6小時產生新檔案, modulate="true" : 產生檔案是否以0點偏移時間,即6點,12點,18點,0點-->
               <TimeBasedTriggeringPolicyinterval="6" modulate="true"/>
               <!-- SizeBasedTriggeringPolicy :檔案大小卷動策略-->
               <SizeBasedTriggeringPolicysize="100 MB"/>
           </Policies>
           <!-- DefaultRolloverStrategy屬性如不設定，則預設為最多同一資料夾下7個檔案，這裡設定了20 -->
           <DefaultRolloverStrategy max="20"/>
       </RollingFile>

       <RollingFile name="RollingFileWarn" fileName="${sys:user.home}/logs/warn.log"
                    filePattern="${sys:user.home}/logs/$${date:yyyy-MM}/warn-%d{yyyy-MM-dd}-%i.log">
           <ThresholdFilter level="warn" onMatch="ACCEPT" onMismatch="DENY"/>
           <PatternLayout pattern="[%d{HH:mm:ss:SSS}] [%p] - %l - %m%n"/>
           <Policies>
               <TimeBasedTriggeringPolicy/>
               <SizeBasedTriggeringPolicy size="100 MB"/>
           </Policies>
       </RollingFile>
       <RollingFile name="RollingFileError" fileName="${sys:user.home}/logs/error.log"
                    filePattern="${sys:user.home}/logs/$${date:yyyy-MM}/error-%d{yyyy-MM-dd}-%i.log">
           <ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY"/>
           <PatternLayout pattern="[%d{HH:mm:ss:SSS}] [%p] - %l - %m%n"/>
           <Policies>
               <TimeBasedTriggeringPolicy/>
               <SizeBasedTriggeringPolicy size="100 MB"/>
           </Policies>
       </RollingFile>
   </appenders>
   <!--3、然後定義logger，只有定義了logger並引入的appender，appender才會生效-->
   <loggers>
       <!--過濾掉spring和mybatis的一些無用的DEBUG資訊-->
       <!--Logger節點用來單獨指定紀錄檔的形式，name為包路徑,比如要為org.springframework包下所有紀錄檔指定為INFO級別等。 -->
       <logger name="org.springframework" level="INFO"></logger>
       <logger name="org.mybatis" level="INFO"></logger>
       <!-- Root節點用來指定專案的根紀錄檔，如果沒有單獨指定Logger，那麼就會預設使用該Root紀錄檔輸出 -->
       <root level="all">
           <appender-ref ref="Console"/>
           <appender-ref ref="RollingFileInfo"/>
           <appender-ref ref="RollingFileWarn"/>
           <appender-ref ref="RollingFileError"/>
       </root>
       <!--AsyncLogger :非同步紀錄檔,LOG4J有三種紀錄檔模式,全非同步紀錄檔,混合模式,同步紀錄檔,效能從高到底,執行緒越多效率越高,也可以避免紀錄檔卡死執行緒情況發生-->
       <!--additivity="false" : additivity設定事件是否在root logger輸出，為了避免重複輸出，可以在Logger 標籤下設定additivity為」false」只在自定義的Appender中進行輸出
-->
       <AsyncLogger name="AsyncLogger" level="trace" includeLocation="true" additivity="false">
           <appender-ref ref="RollingFileError"/>
       </AsyncLogger>
   </loggers>
</configuration>

2.5 使用非同步紀錄檔的注意事項

在使用非同步紀錄檔的時候需要注意一些事項，如下：

不要同時使用AsyncAppender和AsyncLogger，也就是在設定中不要在設定Appender的時候，使用Async標識的同時，又設定AsyncLogger，這不會報錯，但是對於效能提升沒有任何好處。
不要在開啟了全域性同步的情況下，仍然使用AsyncAppender和AsyncLogger。這和上一條是同一個意思，也就是說，如果使用非同步紀錄檔，AsyncAppender、AsyncLogger和全域性紀錄檔，不要同時出現。
如果不是十分必須，不管是同步非同步，都設定immediateFlush為false，這會對效能提升有很大幫助。
如果不是確實需要，不要列印location資訊，比如HTML的location，或者pattern模式裡的%C or $class, %F or %file, %l or %location, %L or %line, %M or %method, 等，因為Log4j需要在列印紀錄檔的時候做一次棧的快照才能獲取這些資訊，這對於效能來說是個極大的損耗。

3 總結

在壓測的中，對於問題的根因盡最大能力探索挖掘，不斷沉澱總結實踐經驗。尤其是一些開源的元件使用，要詳細學習瞭解使用規範以及最佳實踐，必要時可以加入效能測試，確保滿足我們質量和效能要求。

4 參考

作者：京東物流劉江波呂怡浩

來源：京東雲開發者社群自猿其說Tech 轉載請註明來源

log4j2同步紀錄檔引發的效能問題