log4j2同步日誌引發的效能問題

架構師修行手冊發表於2023-10-25

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 結論

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

但是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 使用非同步日誌的注意事項

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

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

3 總結

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

4 參考

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

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

相關文章