這是在公司內(nèi)部的一次升級實踐,刪除了很多隱私的內(nèi)容,所以可能不是很完整。
1、背景
在任何系統(tǒng)中,日志都是非常重要的組成部分,它是反映系統(tǒng)運行情況的重要依據(jù),也是排查問題時的必要線索。絕大多數(shù)人都認可日志的重要性,但是又有多少人仔細想過該怎么打日志,日志對性能的影響究竟有多大呢?
新的Log4j 2.0版本有了大幅的性能提升、新的插件系統(tǒng),以及配置設置方面的很多改善。Log4j 1.x 在高并發(fā)情況下出現(xiàn)死鎖導致cpu使用率異常飆升,而Log4j2.0基于LMAX Disruptor的異步日志在多線程環(huán)境下性能會遠遠優(yōu)于Log4j 1.x和logback ——官方測試結果。
本次升級是以thrift服務化項目為例子進行的,后續(xù)會在其他項目中進行,本次工作內(nèi)容為:Log4j1.x 升級到 Log4j2(如果不想了解原理,可以直接跳到:3、升級方式)
2、log4j2說明
2.1 特性
- API分離: Log4j2將API與實現(xiàn)分離開來(log4j-api: 作為日志接口層,用于統(tǒng)一底層日志系統(tǒng),log4j-core : 作為上述日志接口的實現(xiàn),是一個實際的日志框架)
- 改進的特定: Log4j2的性能在某些關鍵領域比Log4j 1.x更快,而且大多數(shù)情況下與Logback相當。
- 多個API支持:Log4j2提供最棒的性能的同時,還支持SLF4J和公共日志記錄API。
- 自動配置加載:像Logback一樣,一旦配置發(fā)生改變,Log4j2可以自動載入這些更改后的配置信息,又與Logback不同,配置發(fā)生改變時不會丟失任何日志事件。
- 高級過濾功能:與Logback類似,Log4j2可以支持基于上下文數(shù)據(jù)、標記,正則表達式以及日志事件中的其他組件的過濾。
- 插件架構:所有可以配置的組件都以Log4j插件的形式來定義。無需修改任何Log4j代碼就可以創(chuàng)建新的Appender、Layout、Pattern Convert 等等。Log4j自動識別預定義的插件,如果在配置中引用到這些插件,Log4j就自動載入使用。
- 屬性支持:屬性可以在配置文件中引用,也可以直接替代或傳入潛在的組件,屬性在這些組件中能夠動態(tài)解析。屬性可以是配置文件,系統(tǒng)屬性,環(huán)境變量,線程上下文映射以及事件中的數(shù)據(jù)中定義的值。用戶可以通過增加自己的Lookup插件來定制自己的屬性。
- log4j2配置: 不支持properties文件,但卻可以以json文件作為配置
2.2 性能
吞吐量測試

平均耗時

其中:
Loggers mixed sync/async: 同步與異步logger可以混合使用,分別由標簽<logger> <asyncLogger> 指定
異步Logger與異步Appender區(qū)別:AsyncAppender使用ArrayBlockingQueue來處理message,AsyncLogger使用LMAX Disruptor
- AsyncAppender的做法是:應用線程創(chuàng)建LogEvent將其塞入Queue,消費線程取出LogEvent寫磁盤。在這種框架的可擴展性不好,當加倍消費線程時各個線程的吞吐量會減半,所以總吞吐量并不會得到增加。原因是,并發(fā)queue是標準java庫的一部分,會使用鎖來保證數(shù)據(jù)傳遞的正確性。
- LMAX Disruptor是一個無鎖數(shù)據(jù)結構,可以在線程間傳遞消息。詳細介紹可訪問其網(wǎng)站:https://github.com/LMAX-Exchange/disruptor/wiki/Introduction
更多性能測試信息可參考官方報告:
http://logging.apache.org/log4j/2.x/manual/async.html#Performance
http://logging.apache.org/log4j/2.x/performance.html
2.3 主要組件

2.4 配置
Configuration
示例:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
<Properties>
<Property name="pattern_layout">%d %-5p (%F:%L) - %m%n</Property>
<Property name="LOG_HOME">/var/***/logs</Property>
</Properties>
<Appenders>
<Console name="console" target="SYSTEM_OUT" follow="true">
<PatternLayout pattern="${pattern_layout}"/>
</Console>
<RollingRandomAccessFile name="file"
fileName="${LOG_HOME}/${sys:app.key}.log"
filePattern="${LOG_HOME}/${sys:app.key}.log.%d{yyyy-MM-dd}">
<PatternLayout pattern="${pattern_layout}"/>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingRandomAccessFile>
<RollingRandomAccessFile name="access_kpi"
fileName="${LOG_HOME}/${sys:app.key}_access_kpi.log"
filePattern="${LOG_HOME}/${sys:app.key}_access_kpi.log.%d{yyyy-MM-dd}">
<PatternLayout pattern="${pattern_layout}"/>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingRandomAccessFile>
<RollingRandomAccessFile name="jmonitorappender"
fileName="${LOG_HOME}/${sys:app.key}.jmonitor.log"
filePattern="${LOG_HOME}/${sys:app.key}.jmonitor.%d{yyyy-MM-dd}.log.gz">
<PatternLayout pattern="${pattern_layout}"/>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingRandomAccessFile>
<RollingRandomAccessFile name="jmonitorlogstoreappender"
fileName="${LOG_HOME}/${sys:app.key}.jmonitor.logstore.log"
filePattern="${LOG_HOME}/${sys:app.key}.jmonitor.logstore.%d{yyyy-MM-dd}.log.gz">
<PatternLayout pattern="${pattern_layout}"/>
<Policies>
<TimeBasedTriggeringPolicy/>
</Policies>
</RollingRandomAccessFile>
<Scribe name="errorLog">
<ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY"/>
<Property name="hostname">${sys:app.key}</Property>
<Property name="scribeHost">127.0.0.1</Property>
<Property name="scribePort">4252</Property>
<Property name="scribeCategory">cos_errorlog</Property>
<Property name="printExceptionStack">false</Property>
<Property name="addStackTraceToMessage">false</Property>
<Property name="timeToWaitBeforeRetry">6000</Property>
<Property name="sizeOfInMemoryStoreForward">100</Property>
<PatternLayout
pattern="%d %p $${sys:app.host} $${sys:app.ip} errorlog appkey=$${sys:app.key} location=%F:%L rawlog=%replace{%replace{%m}{=}{:}}{\n|\t}{<br/>} rawexception=%replace{%replace{%ex}{=}{:}}{\n|\t}{<br/>}%n"/>
</Scribe>
</Appenders>
<Loggers>
<Logger name="access_kpi" level="INFO" includeLocation="true" additivity="false">
<AppenderRef ref="access_kpi"/>
</Logger>
<!-- tair Loggers -->
<Logger name="com.taobao.tair3.client" level="WARN" includeLocation="true" additivity="false">
<AppenderRef ref="file"/>
<AppenderRef ref="errorLog"/>
</Logger>
<!-- 3rdparty Loggers -->
<Logger name="org.springframework" level="WARN"/>
<Logger name="org.apache.zookeeper" level="ERROR"/>
<Logger name="org.springframework.web" level="WARN"/>
<!-- Root Logger -->
<Root level="INFO" includeLocation="true">
<AppenderRef ref="file"/>
<AppenderRef ref="console"/>
<AppenderRef ref="errorLog"/>
</Root>
</Loggers>
</Configuration>
我們先看看Configuration的一些特性:
- Configuration代表Log4j2的配置文件,它和LoggerContext組件一一對應(關于LoggerContext請看下文),它維護Log4j2各個組件之間的關系,其中,一個Configuration對應多個LoggerConfig組件。
- Configuration可以通過四種方式配置:a)配置文件(XML、JSON和YAML);b)創(chuàng)建ConfigurationFactory和Configuration實現(xiàn);c)通過代碼調(diào)用Configuration的API構造;d)在Logger內(nèi)部調(diào)用API函數(shù)構造。
- Configuration能夠在應用程序初始化的過程中進行自動裝配,其配置內(nèi)容按照一定的順序獲取,詳見:AutomaticConfiguration。
- 當我們給Configuration設置monitorInterval時,這可以使得log4j2階段性的讀取配置文件,并重新構造Configuration。在這一過程中,log4j2不會丟失日志事件。
Configuration標簽
<Configuration status="WARN">
...
</Configuration>
該片段表明log4j2配置文件的所有內(nèi)容都在這個標簽內(nèi),其status屬性為“WARN”說明:log4j2內(nèi)部的日志會將日志級別大于WARN的日志打印到Console。除了該字段,Configuration還包括其他屬性,詳見:ConfigurationSyntax。
Appenders標簽
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
</Console>
</Appenders>
所有的Appender將在<Appenders>和</Appenders>之間定義。上述例子定義了ConsoleAppender并關聯(lián)PatternLayout,關于Appender和Layout請看上述相關小節(jié)。
Logger標簽
<Loggers>
<Logger name="com.foo.Bar" level="trace" additivity="false" includeLocation="true">
<AppenderRef ref="Console"/>
</Logger>
<Root level="error">
<AppenderRef ref="Console"/>
</Root>
</Loggers>
所有的Logger將在<Loggers>和</Loggers>之間定義。上述例子通過<Root>定義了所有Logger的根結點(RootLogger),并通過<AppenderRef>標簽關聯(lián)名稱為“Console”的Appender,關于Logger請看上述相關小節(jié)。
此處有必要說明additivity字段,通過配置該字段,我們可以規(guī)定是否將日志事件傳遞到Logger的父結點處理,其默認值為true(即默認交給parent Logger處理)。
Logger默認不會獲取location信息,因此,若我們的Layout或Filter等需要location信息,我們必須給相應的設置“includeLocation=true”
Filters標簽
<Filters>
<Marker marker="EVENT" onMatch="ACCEPT" onMismatch="NEUTRAL"/>
<DynamicThresholdFilter key="loginId" defaultThreshold="ERROR" onMatch="ACCEPT" onMismatch="NEUTRAL">
<KeyValuePair key="User1" value="DEBUG"/>
</DynamicThresholdFilter>
</Filters>
log4j2還有一個很重要的組件——Filter,詳見Filter小節(jié)。此處通過<Filters>和</Filters>表明這是一個組合Filter,里邊包括MarkerFilter和DynamicThresholdFilter。onMatch表示和onMismatch表示經(jīng)過Filter過濾后的結果,該結果有三個取值:ACCEPT、NEUTRAL和DENY。log4j2在處理LogEvents時,會通過該Filter進行過濾,若返回結果為ACCEPT,則直接處理(略過其它Filter和日志級別的過濾);若返回DENY則直接終止該LogEvents;若返回NEUTRAL,則不做決策,讓后續(xù)代碼做處理。
此處,F(xiàn)ilter是通過Configuration的直接子元素配置,因此,LogEvents若被該Filter過濾之后則不會傳遞給Logger處理。
2.5 異步日志
Log4j2提供了異步Logger,通過不同線程實現(xiàn)I/O操作,目的在于為我們的應用程序提高性能。我們先來看一看它主要在哪些方面做改進:
- Asynchronous Loggers。異步日志器是Log4j2新增的日志器,它的目的是讓我們的應用程序在調(diào)用Logger.log()打印日志時立馬返回。我們可以在程序中全部使用異步日志器,也可以使用混合的日志器,前者能給我們的程序帶來很大的性能提升,而后者讓我們的程序足夠靈活。
- LMAX Disruptor技術。異步日志器在其內(nèi)部實現(xiàn)采用了Disruptor技術,相對于使用BlockingQueue,它提高了吞吐量和降低延時。
- Asynchronous Appender。該組件在Log4j1.x已經(jīng)存在,但是Log4j2實現(xiàn)的異步Appender使得每次寫入磁盤時,都會進行flush操作,效果和配置“immediateFlush=true”一樣。該異步Appender內(nèi)部采用ArrayBlockingQueue的方式,因此不需要引入disruptor依賴。
- RandomAccessFileAppender。該Appender采用ByteBuffer+RandomAccessFile替代了BufferedOutputStream,官方給出的測試數(shù)據(jù)是它將速度提升了20-200%。
AsyncLoggers雖然帶來了極大的性能提升,我們應該經(jīng)常使用。不過,它也有一些缺點,因此,我們要根據(jù)具體的應用場景決定使用同步還是異步的方式,詳見:Trade-offs。
3、升級方式
以下開始說明***服務化項目如何由:Log4j1.x 升級到 Log4j2
3.1 排除對log4j的依賴
需要確定項目pom文件中依賴的其他的jar中也不再依賴log4j及slf4j-log4j12,具體方式可以通過IDE提供的功能或者直接使用mvn dependency:tree確定依賴關系。
由于引用的jar中很多依然使用的為log4j,因此已經(jīng)升級過log4j2的項目,每次在新增依賴的時候,一定需要確定一下,引用的jar是否含有對低版本的依賴,并且exclusion掉。
<exclusions>
<exclusion>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-log4j12</artifactId>
</exclusion>
<exclusion>
<groupId>log4j</groupId>
<artifactId>log4j</artifactId>
</exclusion>
</exclusions>
3.2 添加對log4j2的依賴
<properties>
<org.slf4j-version>1.7.12</org.slf4j-version>
<log4j2-version>2.3</log4j2-version>
</properties>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>jcl-over-slf4j</artifactId>
<version>${org.slf4j-version}</version>
<scope>runtime</scope>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-1.2-api</artifactId>
<version>${log4j2-version}</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-slf4j-impl</artifactId>
<version>${log4j2-version}</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-api</artifactId>
<version>${log4j2-version}</version>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-core</artifactId>
<version>${log4j2-version}</version>
</dependency>
<dependency>
<groupId>com.lmax</groupId>
<artifactId>disruptor</artifactId>
<version>3.2.0</version>
</dependency>
<dependency>
<groupId>com.sankuai.meituan</groupId>
<artifactId>scribe-log4j2</artifactId>
<version>1.0.9</version>
</dependency>
3.3 JVM參數(shù)
在JVM啟動參數(shù)中增加 -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector 開啟異步日志。(目前針對scribe的appender為同步appender,如果不開啟異步機制會導致線程block)
3.4 XML配置
刪除原log4j.xml配置文件,新增log4j2.xml,注意:需要保證log4j2.xml在resource根目錄內(nèi),否則會導致配置文件加載不到(即log4j2.xml需要在class根目錄內(nèi))
注意事項
- includeLocation:Logger默認不會獲取location信息,因此,若我們的Layout或Filter等需要location信息,我們必須給相應的設置“includeLocation=true”
- additivity:通過配置該字段,我們可以規(guī)定是否將日志事件傳遞到Logger的父結點處理,其默認值為true
- file文件的路徑,由于啟動腳本及服務器變量配置等的不確定性,因此該處建議直接配置絕對路徑,可以使用<Property name="LOG_HOME">/var/***/logs</Property>配置在xml中,也可以通過JVM參數(shù) -Dapp.logdir=$LOG_HOME等方式
- AsyncLogger為異步日志,需要添加JVM參數(shù)-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector
- 服務化項目啟動腳本里如果對啟動日志做重定向了“>>
LOGFILE 2>&1”,請不要使用Console輸出日志,否則會導致重定向的日志文件將重復打印所有日志信息
- 服務化項目不需要配置access_kpi的日志打印
- Scribe說明(線上異常監(jiān)控接入說明#線上異常監(jiān)控接入說明-log4j2.0)
- hostname:這里獲取的是java啟動時配置的系統(tǒng)參數(shù)
- scribeCategory:這里寫死“cos_errorlog”,這樣數(shù)據(jù)組才知道這套日志需要發(fā)送給sg-errlog系統(tǒng)
- pattern:按照數(shù)據(jù)組的要求打印日志,同時將“等號”和“回車”等替換為對應的占位符
- scribeHost:scribeHost:測試環(huán)境為10.4.232.70,如果服務器上有采集器監(jiān)聽,則可以配置127.0.0.1
3.5 Log定義
private static final Logger LOGGER = LoggerFactory.getLogger(Boot.class);
使用slf4j進行l(wèi)og的定義,注意需要保證項目中不再依賴于slf4j1。如果啟動時有如下提示,說明依然依賴了多個slf4j

4、參考資料
http://logging.apache.org/log4j/2.x/manual/migration.html#Configuring_Log4j_2
http://logging.apache.org/log4j/2.x/guidelines.html
http://logging.apache.org/log4j/2.x/performance.html
http://www.infoq.com/cn/articles/things-of-java-log-performance
http://www.infoq.com/cn/news/2014/08/apache-log4j2
個人介紹:
高廣超 :多年一線互聯(lián)網(wǎng)研發(fā)與架構設計經(jīng)驗,擅長設計與落地高可用、高性能互聯(lián)網(wǎng)架構。目前就職于美團網(wǎng),負責核心業(yè)務研發(fā)工作。