一、問題回顧

1.1 問題描述

在項目的性能測試中，相關(guān)的接口的隨著并發(fā)數(shù)增加，接口的響應(yīng)時間變長，接口吞吐不再增長，應(yīng)用的CPU使用率較高。

1.2 分析思路

誰導(dǎo)致的CPU較高，阻塞接口TPS的增長？接口的響應(yīng)時間的調(diào)用鏈分布是什么樣的，有沒有慢的點？

1）使用火焰圖分析應(yīng)用的CPU如下，其中l(wèi)og4j2日志占了40%左右CPU，初步懷疑是log4j2的問題。

2）調(diào)用鏈的分析

通過pfinder查看調(diào)用鏈發(fā)現(xiàn)，接口總耗時78ms，沒有明顯慢的調(diào)用方法和慢sql等，先排除接口的本身的代碼問題。

1.3 初步結(jié)論

log4j2的問題，需詳細(xì)分析日志的相關(guān)配置log4j2.xml。

上面可以看到日志中Loggers節(jié)點下的節(jié)點以及節(jié)點都是打印的同步日志。同步日志是程序的業(yè)務(wù)邏輯和日志輸出語句均在一個線程運行，當(dāng)日志較多，在一定程度上阻塞了業(yè)務(wù)的運行效率。改成異步日志試一下：

改成異步日志配置：使用AsyncLogger

1.4 回歸驗證

同步日志改成異步日志后。同樣10并發(fā)，接口的TP99由 51ms 降到 23ms，接口的吞吐TPS由 493提高到 1078，應(yīng)用的CPU由 82%降到 57%。

完美end。問題解決了，但是log4j2的日志我們還是要詳細(xì)研究學(xué)習(xí)一下。

1.5 結(jié)論

log4j2使用異步日志將大幅提升性能，減少對應(yīng)用本身的影響。
從根本上減少不必要日志的輸出。

但是log4j2異步日志是怎么實現(xiàn)的和同步日志有什么區(qū)別？為什么異步日志的的效率更高？引發(fā)我去學(xué)習(xí)一下log4j2的相關(guān)知識，下面和大家分享一下：

二、log4j2日志

2.1 log4j2的優(yōu)勢

log4j2是log4j 1.x 的升級版，參考了logback的一些優(yōu)秀的設(shè)計，并且修復(fù)了一些問題，因此帶來了一些重大的提升，主要有：

異常處理，在logback中，Appender中的異常不會被應(yīng)用感知到，但是在log4j2中，提供了一些異常處理機制。
性能提升， log4j2相較于log4j 1和logback都具有很明顯的性能提升，后面會有官方測試的數(shù)據(jù)。
自動重載配置，參考了logback的設(shè)計，當(dāng)然會提供自動刷新參數(shù)配置，最實用的就是我們在生產(chǎn)上可以動態(tài)的修改日志的級別而不需要重啟應(yīng)用——那對監(jiān)控來說，是非常敏感的。
無垃圾機制，log4j2在大部分情況下，都可以使用其設(shè)計的一套無垃圾機制，避免頻繁的日志收集導(dǎo)致的jvm gc。

2.2 Log4J2日志分類

Log4j2中記錄日志的方式有同步日志和異步日志兩種方式，其中異步日志又可分為使用AsyncAppender和使用AsyncLogger兩種方式。使用LOG4J2有三種日志模式,全異步日志,混合模式,同步日志,性能從高到低,線程越多效率越高,也可以避免日志卡死線程情況發(fā)生。

同步和異步日志的性能對比：

2.3 同步日志

使用log4j2的同步日志進(jìn)行日志輸出，日志輸出語句與程序的業(yè)務(wù)邏輯語句將在同一個線程運行，即當(dāng)輸出日志時，必須等待日志輸出語句執(zhí)行完畢后，才能執(zhí)行后面的業(yè)務(wù)邏輯語句。

2.4 異步日志

而使用異步日志進(jìn)行輸出時，日志輸出語句與業(yè)務(wù)邏輯語句并不是在同一個線程中運行，而是有專門的線程用于進(jìn)行日志輸出操作，處理業(yè)務(wù)邏輯的主線程不用等待即可執(zhí)行后續(xù)業(yè)務(wù)邏輯。

log4j2最大的特點就是異步日志，其性能的提升主要也是從異步日志中受益，我們來看看如何使用log4j2的異步日志

Log4j2中的異步日志實現(xiàn)方式有AsyncAppender和AsyncLogger兩種。
其中：

AsyncAppender采用了ArrayBlockingQueue來保存需要異步輸出的日志事件；
AsyncLogger則使用了Disruptor框架來實現(xiàn)高吞吐。

注意這是兩種不同的實現(xiàn)方式，在設(shè)計和源碼上都是不同的體現(xiàn)。

2.4.1 AsyncAppender

AsyncAppender是通過引用別的Appender來實現(xiàn)的，當(dāng)有日志事件到達(dá)時，會開啟另外一個線程來處理它們。需要注意的是，如果在Appender的時候出現(xiàn)異常，對應(yīng)用來說是無法感知的。AsyncAppender應(yīng)該在它引用的Appender之后配置，默認(rèn)使用 java.util.concurrent.ArrayBlockingQueue實現(xiàn)而不需要其它外部的類庫。當(dāng)使用此Appender的時候，在多線程的環(huán)境下需要注意，阻塞隊列容易受到鎖爭用的影響，這可能會對性能產(chǎn)生影響。

<?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進(jìn)行配置直接引用上面的RollingFile的name--> <Async name="Async">        <AppenderRef ref="RollingFileError"/> </Async> <!--異步AsyncAppender配置完畢，需要幾個配置幾個--> </Appenders> <Loggers>         <Root level="error">          <!--此處如果引用異步AsyncAppender的name就是異步輸出日志-->         <!--此處如果引用Appenders標(biāo)簽中RollingFile的name就是同步輸出日志-->          <AppenderRef ref="Async"/></Root> </Loggers></Configuration>

2.4.2 AsyncLogger

AsyncLogger才是log4j2 的重頭戲，也是官方推薦的異步方式。它可以使得調(diào)用Logger.log返回的更快。Log4j2中的AsyncLogger的內(nèi)部使用了Disruptor框架。

Disruptor簡介

Disruptor是英國外匯交易公司LMAX開發(fā)的一個高性能隊列，基于Disruptor開發(fā)的系統(tǒng)單線程能支撐每秒600萬訂單。
目前，包括Apache Strom、Log4j2在內(nèi)的很多知名項目都應(yīng)用了Disruptor來獲取高性能。
Disruptor框架內(nèi)部核心數(shù)據(jù)結(jié)構(gòu)為RingBuffer，其為無鎖環(huán)形隊列。

Disruptor為什么這么快？

lock-free-使用了CAS來實現(xiàn)線程安全
使用緩存行填充解決偽共享問題

異步日志可以有兩種選擇：全局異步和混合異步。

1）全局異步

全局異步就是，所有的日志都異步的記錄，在配置文件上不用做任何改動，只需要在jvm啟動的時候增加一個參數(shù)；這是最簡單的配置，并提供最佳性能。
然后在src/java/resources目錄添加log4j2.component.properties配置文件

設(shè)置異步日志系統(tǒng)屬性

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

2）混合異步

混合異步就是，你可以在應(yīng)用中同時使用同步日志和異步日志，這使得日志的配置方式更加靈活。因為Log4j文檔中也說了，雖然Log4j2提供一套異常處理機制，可以覆蓋大部分的狀態(tài)，但是還是會有一小部分的特殊情況是無法完全處理的，比如我們?nèi)绻怯涗泴徲嬋罩?，那么官方就推薦使用同步日志的方式，而對于其他的一些僅僅是記錄一個程序日志的地方，使用異步日志將大幅提升性能，減少對應(yīng)用本身的影響?；旌袭惒降姆绞叫枰ㄟ^修改配置文件來實現(xiàn)，使用AsyncLogger標(biāo)記配置。

第一步：pom中添加相關(guān)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"?><!--日志級別以及優(yōu)先級排序: OFF > FATAL > ERROR > WARN > INFO > DEBUG > TRACE > ALL --> <!--status="WARN" :用于設(shè)置log4j2自身內(nèi)部日志的信息輸出級別，默認(rèn)是OFF--> <!--monitorInterval="30" :間隔秒數(shù),自動檢測配置文件的變更和重新配置本身--><configuration status="WARN" monitorInterval="30">   <Properties>       <!--1、自定義一些常量，之后使用${變量名}引用-->       <Property name="logFilePath">log</Property>       <Property name="logFileName">test.log</Property>   </Properties>   <!--2、appenders:定義輸出內(nèi)容,輸出格式,輸出方式,日志保存策略等,常用其下三種標(biāo)簽[console,File,RollingFile]-->   <!--Appenders中配置日志輸出的目的地           console只的是控制臺 system.out.println           rollingFile 只的是文件大小達(dá)到指定尺寸的時候產(chǎn)生一個新的文件-->   <appenders>       <!--console :控制臺輸出的配置-->       <console name="Console" target="SYSTEM_OUT">           <!--PatternLayout :輸出日志的格式,LOG4J2定義了輸出代碼,詳見第二部分 %p 輸出優(yōu)先級，即DEBUG，INFO，WARN，ERROR，F(xiàn)ATAL-->           <PatternLayout pattern="[%d{HH:mm:ss:SSS}] [%p] - %l - %m%n"/>       </console>       <!--File :同步輸出日志到本地文件-->       <!--append="false" :根據(jù)其下日志策略,每次清空文件重新輸入日志,可用于測試-->       <File name="log" fileName="${logFilePath}/${logFileName}" append="false">           <!-- 格式化輸出：           %d表示日期，%thread表示線程名，           %-5level：級別從左顯示5個字符寬度           %thred: 輸出產(chǎn)生該日志事件的線程名           %class：是輸出的類           %L: 輸出代碼中的行號           %M：方法名           %msg：日志消息，           %n是換行符           %c: 輸出日志信息所屬的類目，通常就是所在類的全名            %t: 輸出產(chǎn)生該日志事件的線程名            %l: 輸出日志事件的發(fā)生位置，相當(dāng)于%C.%M(%F:%L)的組合,包括類目名、發(fā)生的線程，以及在代碼中的行數(shù)。舉例：Testlog4.main(TestLog4.Java:10)            %p: 輸出日志信息優(yōu)先級，即DEBUG，INFO，WARN，ERROR，F(xiàn)ATAL,           2020.02.06 at 11:19:54 CST INFOcom.example.redistest.controller.PersonController 40 setPerson - 添加成功1條數(shù)據(jù)           -->           <!-- %class{36} 表示 class 名字最長36個字符 -->           <PatternLayout pattern="%d{HH:mm:ss.SSS} %-5level %class{36} %L %M - %msg%xEx%n"/>       </File>       <!--       關(guān)鍵點在于 filePattern后的日期格式，以及TimeBasedTriggeringPolicy的interval，日期格式精確到哪一位，interval也精確到哪一個單位.       1） TimeBasedTriggeringPolicy需要和filePattern配套使用，由于filePattern配置的時間最小粒度如果設(shè)置是dd天，所以表示每一天新建一個文件保存日志。       2） SizeBasedTriggeringPolicy表示當(dāng)文件大小大于指定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 :時間滾動策略,默認(rèn)0點小時產(chǎn)生新的文件,interval="6" : 自定義文件滾動時間間隔,每隔6小時產(chǎn)生新文件, modulate="true" : 產(chǎn)生文件是否以0點偏移時間,即6點,12點,18點,0點-->               <TimeBasedTriggeringPolicyinterval="6" modulate="true"/>               <!-- SizeBasedTriggeringPolicy :文件大小滾動策略-->               <SizeBasedTriggeringPolicysize="100 MB"/>           </Policies>           <!-- DefaultRolloverStrategy屬性如不設(shè)置，則默認(rèn)為最多同一文件夾下7個文件，這里設(shè)置了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節(jié)點用來單獨指定日志的形式，name為包路徑,比如要為org.springframework包下所有日志指定為INFO級別等。 -->       <logger name="org.springframework" level="INFO"></logger>       <logger name="org.mybatis" level="INFO"></logger>       <!-- Root節(jié)點用來指定項目的根日志，如果沒有單獨指定Logger，那么就會默認(rèn)使用該Root日志輸出 -->       <root level="all">           <appender-ref ref="Console"/>           <appender-ref ref="RollingFileInfo"/>           <appender-ref ref="RollingFileWarn"/>           <appender-ref ref="RollingFileError"/>       </root>       <!--AsyncLogger :異步日志,LOG4J有三種日志模式,全異步日志,混合模式,同步日志,性能從高到底,線程越多效率越高,也可以避免日志卡死線程情況發(fā)生-->       <!--additivity="false" : additivity設(shè)置事件是否在root logger輸出，為了避免重復(fù)輸出，可以在Logger 標(biāo)簽下設(shè)置additivity為”false”只在自定義的Appender中進(jìn)行輸出-->       <AsyncLogger name="AsyncLogger" level="trace" includeLocation="true" additivity="false">           <appender-ref ref="RollingFileError"/>       </AsyncLogger>   </loggers></configuration>

2.5 使用異步日志的注意事項

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

不要同時使用AsyncAppender和AsyncLogger，也就是在配置中不要在配置Appender的時候，使用Async標(biāo)識的同時，又配置AsyncLogger，這不會報錯，但是對于性能提升沒有任何好處。
不要在開啟了全局同步的情況下，仍然使用AsyncAppender和AsyncLogger。這和上一條是同一個意思，也就是說，如果使用異步日志，AsyncAppender、AsyncLogger和全局日志，不要同時出現(xiàn)。
如果不是十分必須，不管是同步異步，都設(shè)置immediateFlush為false，這會對性能提升有很大幫助。
如果不是確實需要，不要打印location信息，比如HTML的location，或者pattern模式里的%C or $class, %F or %file, %l or %location, %L or %line, %M or %method, 等，因為Log4j需要在打印日志的時候做一次棧的快照才能獲取這些信息，這對于性能來說是個極大的損耗。

三、總結(jié)

在壓測的中，對于問題的根因盡最大能力探索挖掘，不斷沉淀總結(jié)實踐經(jīng)驗。尤其是一些開源的組件使用，要詳細(xì)學(xué)習(xí)了解使用規(guī)范以及最佳實踐，必要時可以加入性能測試，確保滿足我們質(zhì)量和性能要求。

參考資料

[1] https://www.yisu.com/zixun/623058.html

[2] https://www.jianshu.com/p/9f0c67facbe2

[3] https://blog.csdn.net/thinkwon/article/details/101625124

[4] https://zhuanlan.zhihu.com/p/386990511

-end-

log4j2同步日志引發(fā)的性能問題