1. 程式人生 > >Log4j 1.x 升級 Log4j 2.x (調研和升級)

Log4j 1.x 升級 Log4j 2.x (調研和升級)

因為公司業務需要,目前的log4j 1.x 遇到死鎖,需要升級到Log4j 2.x。現在對目前的日誌框架進行調研,並根據目前的現狀提出升級的方法。

一引言
對於一個應用程式來說日誌記錄是必不可少的一部分。線上問題追蹤,基於日誌的業務邏輯統計分析等都離不日誌。Java領域存在多種框架,目前比較常用的日誌框架包括:Log4j、Log4J2、Commons Logging、Slf4j、Logback和Jul。Log4j是一個基於Java的日誌記錄工具。它是由Ceki Gülcü首創的,現在則是Apache軟體基金會的一個專案。Log4j 2是apache開發的一款Log4j的升級產品。Commons Logging Apache基金會所屬的專案,是一套Java日誌介面,之前叫Jakarta Commons Logging,後更名為Commons Logging。Slf4j 類似於Commons Logging,是一套簡易Java日誌門面,本身並無日誌的實現。(Simple Logging Facade for Java,縮寫Slf4j)。Logback 一套日誌元件的實現(slf4j陣營)。Jul (Java Util Logging),自Java1.4以來的官方日誌實現。
由於目前公司使用的日誌系統是以Log4j 1.x 為主,Log4J 1.x由於已經停止更新和維護,其中存在的訊息丟失和阻塞問題嚴重,所以對現有點的業務造成的很大的影響。同時由於各個系統使用的日誌框架混亂,在系統中同時使用Log4j1.x、JDK自帶的Logging和Logback。所以需要統一升級一下框架。
目前業界主要使用的是Log4j1.x、Log4j 2.x和logback。由於Log4j 2 是 Log4j 的升級版本,該版本比起前任來說有著顯著的改進,包含很多在 Logback 中的改進以及Logback 架構中存在的問題。所以本文會根據日誌的發展路線著重調研Log4j1.x中存在的問題,以及logback和Log4j2.x的優點。最後給出日誌系統版本升級的建議。

二調研物件
1 log4j 1.x
Log4j是Apache的一個開放原始碼專案,通過使用Log4j,我們可以控制日誌資訊輸送的目的地是控制檯、檔案、GUI元件、甚至是套介面伺服器、NT的事件記錄器、UNIX Syslog守護程序等;我們也可以控制每一條日誌的輸出格式;通過定義每一條日誌資訊的級別,我們能夠更加細緻地控制日誌的生成過程。最令人感興趣的就是,這些可以通過一個配置檔案來靈活地進行配置,而不需要修改應用的程式碼。
Log4j主要有三個元件:Loggers(記錄器),Appenders (輸出源)和Layouts(佈局),這裡可簡單理解為日誌類別,日誌要輸出的地方和日誌以何種形式輸出。綜合使用這三個元件可以輕鬆的記錄資訊的型別和級別,並可以在執行時控制日誌輸出的樣式和位置。一個典型的Log4j的配置檔案log4j.properties如下圖1-1所示:
這裡寫圖片描述


圖1-1
其中info代表的是記錄器的級別,console代表的是記錄器的名稱,下面四行是對記錄器console的配置。
在使用Log4j 1.x過程中出現了一些問題,如死鎖、記憶體溢位和效率不高等現象。
2 logback 相對於Log4j 1.x的改進
Logback是由log4j創始人Ceki 設計的又一個開源日誌元件,用來取代log4j的一個日誌框架,是slf4j的原生實現。logback當前分成三個模組:logback-core、logback- classic和logback-access。
logback-core是其它兩個模組的基礎模組,而logback-classic是log4j的一個改良版本,同時它完整實現了slf4j API,使你可以很方便地更換成其它日誌系統如log4j或JDK14 Logging等。logback-access提供了訪問模組與Servlet容器整合提供通過Http來訪問日誌的功能。
2.1更快的執行速度

在Log4j 1.x 的基礎上,logback 重寫了內部的實現,在某些特定的場景上面,甚至可以比之前的速度快上10倍。比如Logback內部的訊息佇列採用了ArrayBlockingQueue,相對於原始的ArrayList和鎖操作來說,管程類的訊息佇列擁有更好地效能。同時在保證logback的元件更加快速的同時,同時所需的記憶體更加少。
2.2實現SLF4J
logback-classic中的類自然的實現了SLF4J。使用 logback-classic作為底層實現時,涉及到LF4J日記系統的問題你完全不需要考慮。更進一步來說,由於 logback-classic強烈建議使用SLF4J作為客戶端日記系統實現,如果需要切換到log4j或者其他,只需要替換一個jar包即可,不需要去改變那些通過SLF4J API 實現的程式碼。這可以大大減少更換日記系統的工作量。
2.3自動重新載入配置檔案
Logback-classic可以在配置檔案被修改後,自動重新載入。這個掃描過程很快,無資源爭用,並且可以動態擴充套件支援在上百個執行緒之間每秒上百萬個呼叫。它和應用伺服器結合良好,並且在JEE環境通用,因為它不會呼叫建立一個單獨的執行緒來做掃描。
但是由於Logback更新配置時,只是簡單的丟棄未處理的日誌資訊,所以無法作為審計日誌框架,但是Log4j 2.x 很完美的解決了事件丟失的問題。
2.4 I/O錯誤恢復
FileAppender和它的子類,包括RollingFileAppender,可以很容易的從I/O錯誤中恢復。所以,如果一個檔案伺服器臨時宕機,不需要重啟應用,而日誌功能就能正常工作。當檔案伺服器恢復工作,logback相關的appender就會透明地和快速的從上一個錯誤中恢復。
2.4自動清除舊的日誌檔案
通過設定TimeBasedRollingPolicy 或者 SizeAndTimeBasedFNATP的 maxHistory 屬性,可以控制日誌檔案的最大數量。當超出規定的數量事,新的檔案會刪除舊的檔案。如果回滾策略是每月回滾的,比如儲存一年的日誌,可以設定maxHistory屬性為12。對於12個月之前的歸檔日誌檔案將被自動清除。
2.5自動壓縮歸檔日誌檔案
RollingFileAppender可以在回滾操作中,自動壓縮歸檔日誌檔案。壓縮通常是非同步執行的,所以即使是很大的日誌檔案,應用都不會因此而被阻塞。
2.6配置檔案中的條件處理
由於需要在不同的目標環境中變換logback的配置檔案,例如開發環境,測試環境和生產環境。這些配置檔案大體是一樣的,除了某部分會有不同。為了避免重複,logback支援配置檔案中的條件處理,只需使用,和,那麼同一個配置檔案就可以在不同的環境中使用了。如下圖所示:

2.7堆疊軌跡資訊包含包的資料
當logback列印一個異常,堆疊軌跡資訊將包含包的相關資料。下面是一個通過 logback-demo 生成的堆疊資訊:

從上面的資訊,可以看出這個應用使用Struts 1.2.9 而且是使用 jetty 6.1.12部署的。所以,堆疊軌跡資訊顯示關於異常發生的類還有包和包的版本。作為一個開發人員,可以快速的判斷目前系統使用的版本,並且根據相應的版本解決出現的bug。

3 log4j2.x 的突出的改進
Log4j 2是對Log4j1.x 的升級,它比其前身Log4j 1.x提供了顯著的改進,並提供了Logback中許多可用的改進功能,同時修復了Logback架構中的一些固有問題。

3.1 高併發和低延遲
高併發和低效能只要是針對Log4j的非同步日誌記錄來說的。雖然由於Log4j 2.x 由於充分利用Java 5的併發特性(主要是使用了一些concurrent包下鎖),使得效能得到一定的改善,但是Log4j 2.x中的非同步日誌器(Asynchronous Loggers)的高併發和低延遲才是這個日誌框架的亮點。
在Log4j 1.x 中,使用AsyncAppender類來非同步收集日誌。它的底層實現是使用了普通的ArrayList,沒有采用基於管程的BlockingQueue,並結合條件佇列操作wait, notifty來實現阻塞佇列。預設容量是128個LoggingEvent。由於內部使用了大量的鎖(synchronized),在高併發的情況下影響了系統的非同步效能。
而Lockback內部採用的是ArrayBlockingQueue,相比Log4 1.x來說,效能有了很大的提高。
在Log4j 2.x中,Asynchronous Loggers是Log4j2新增的日誌器,非同步日誌器在其內部實現採用了LMAX Disruptor(一個無鎖的執行緒間通訊庫)技術,Disruptor主要通過環形陣列結構、元素位置定位和精巧的無鎖設計(CAS)實現了在高併發情形下的高效能。而且Log4j 2.x中Asynchronous Appenders作為Asynchronous Loggers工作的一部分,效果進行了增強。每次寫入磁碟時,都會進行flush操作,效果和配置“immediateFlush=true”一樣。該非同步Appender內部採用ArrayBlockingQueue的方式,因此不需要引入disruptor依賴。RandomAccessFileAppender採用ByteBuffer+RandomAccessFile替代了BufferedOutputStream,官方給出的測試資料是它將速度提升了20-200%。
以下是Disruptor論文中講述的一個實驗:
2.4G 6核 64位的計數器累加5億次
Method Time (ms)
Single thread 300
Single thread with CAS 5,700
Single thread with lock 10,000
Single thread with volatile write 4,700
Two threads with CAS 30,000
Two threads with lock 224,000

CAS操作比單執行緒無鎖慢了1個數量級;有鎖且多執行緒併發的情況下,速度比單執行緒無鎖慢3個數量級。可見無鎖速度最快。單執行緒情況下,不加鎖的效能 > CAS操作的效能 > 加鎖的效能。在多執行緒情況下,為了保證執行緒安全,必須使用CAS或鎖,這種情況下,CAS的效能超過鎖的效能,前者大約是後者的8倍。加鎖的效能是最差的。
同時在Log4j 2.x中,支援Logger和Appender的同步和非同步,既可以只是用同步,也可以同步和非同步混合使用。全非同步模式的效能要高於混合非同步模式,但是如果Log4j2用作審計功能(Audit)的話,建議使用混合非同步模式。

下面是Log4j 2.x比較了同步Loggers,Asynchronous Appenders和Asynchronous Loggers的吞吐量。(來自官網):

在64個執行緒的測試中,Asynchronous Loggers比asynchronous appenders快12倍,比Synchronous Loggers速度快了68倍。而不管進行日誌記錄的執行緒數量如何,Asynchronous Loggers的吞吐量隨著執行緒數量的增加而增加,而Synchronous Loggers和asynchronous appenders都具有或多或少的恆定吞吐量。

3.2 自動載入配置檔案
Log4j 2.x 和Logback都新增了自動載入日誌配置檔案的功能,又與Logback不同,配置發生改變時不會丟失任何日誌事件。當Log4j 2.x中配置發生改變時,如果還有日誌事件尚未處理,Log4j 2會繼續處理,當處理完成後,Logger會重新指向新配置的LoggerConfig物件,並且刪除無用的物件。
Log4j 2.x能夠自動檢測配置檔案的更改並重新配置自身。如果在配置元素上指定了monitorInterval屬性,並將其設定為非零值,則在下次評估和/或記錄日誌事件並自上次檢查以來已經過了monitorInterval時,將檢查該檔案。下面的示例顯示瞭如何配置屬性,以便只有在至少600秒後才會檢查配置檔案的更改。最小間隔為5秒。

monitorInterval=”600” 指log4j2每隔600秒(10分鐘),自動監控該配置檔案是否有變化,如果變化,則自動根據檔案內容重新配置。
需要注意的是Log4j 2.4之前的版本並不支援.properties屬性檔案。只支援xml、json、jsn 三種格式。從Log4j 2.x及以後的版本增加了對.properties屬性檔案解析支援,但是Log4j 2.x 的配置檔案是不相容Log4j 1.x的。
3.4 死鎖問題的解決
在Log4j 1.x中同步寫日誌的時候,在高併發情況下出現死鎖導致cpu使用率異常飆升。其中的原因是當一個程序寫日誌的時候需要獲取到Logger和Appender。org.apache.log4j.Logger類繼承於org.apache.log4j.Category、Appender繼承於org.apache.log4j.AppenderSkeleton。通過如下Log4j 1.x中Category原始碼和Appender原始碼可以知道,當多執行緒併發時,可能會因為相互持有Logger和Appender發生死鎖。

                    圖3-2 Category原始碼

圖3-3 Appender原始碼

而在log4j 2.x中充分利用Java5的併發支援,並且以最低級別執行鎖定。在Log4j2.x中同步日誌的輸出過程過獲得共享資源(LoggerConfig)的方式採用的是原子變數和concurrent包下的鎖。原子變數(CAS)的效能將超過鎖的效能。同時原子變數不會有死鎖等活躍性問題,達到了解決Lo4j 1.x有死鎖的bug。同時concurrent包下的鎖大大提高了併發程式的效能。Logback中同樣修復了log4j 1.x的很多bug,但是,logback中的有很多類採用同步機制(這種機制導致效能下降)。

3.5更加先進的API
在Log4j 1.x版本中,如果未使用SLF4J門面日誌框架,通常我們會像如下方式記錄日誌:

這種記錄方式使得日誌的記錄像是業務邏輯的一部分,脫離的日誌本質。如果有人忘記寫if語句,程式輸出中會多出很多不必要的字串,同時存在的很大問題就是記憶體溢位和兩次校驗日誌級別的問題。目前Log4j2.x,採用如下的方式進行記錄日誌,字串的拼接會在日誌級別的判斷之後進行。

在版本2.4中,Logger介面增加了對lambda表示式的支援,不過需要Java 8的支援。這允許客戶端程式碼在不顯式檢查所請求的日誌級別是否啟用的情況下延遲日誌記錄。只有當這個日誌級別是啟用的時候才有效。不再需要通過程式碼檢查該級別的日誌是否啟用,使得程式碼更加簡潔。程式碼如下所示:

先進的API使得垃圾產生的數量減少,減少記憶體GC的次數。防止垃圾回收是通過避免建立臨時物件來實現的,這意味著需要儘可能的複用已經存在的物件。目前Log4j2.6及以上版本的部分Appenders、Filters和Layouts支援免垃圾模式。部分被複用的物件儲存在ThreadLocal區域中,但是對於web應用可能會引起記憶體洩漏。
應用伺服器可能會將ThreadLocal儲存線上程池中,這意味著即使應用被解除安裝,用於日誌記錄的物件仍然會保持引用。因此,通過ThreadLocal來複用物件的功能在web應用程式中預設是關閉的。
log4j防止觸發垃圾回收的另一個方式是在將文字轉換為字元陣列的時候複用緩衝區且該功能預設是開啟的。然而使用同步日誌記錄器的多執行緒應用程式可能會有效能影響,因為不同的執行緒需要競爭共享的緩衝區。如果遇到這種情況,應該優先使用非同步日誌記錄器,或者禁用共享緩衝區。
API本身也已經為避免建立臨時物件而修改。除了之前支援簡單可變長度引數(這樣會建立一個臨時資料)的方法之外,log4j新增了所有方法的過載版本,最多支援10個引數。呼叫方法超過10個引數仍然會使用可變長度引數,這將會建立臨時陣列。
這個限制對於通過SLF4J使用log4j的場景影響較大,因為這個門面庫只提供了最多兩個引數的非變長引數。使用者如果希望使用超過兩個引數,並執行在免垃圾回收模式,就需要拋棄SLF4J。

3.6 更加靈活地屬性引用
在複雜的專案中,可能有一些約定的屬性比如專案名稱、配置檔案路徑等等。這些屬性可能會在多個日誌的配置中用到。這樣就可以將這些屬性配置到Log4j2的配置檔案中,方便在多個Logger中共享。
定義屬性需要在配置檔案中新增properties節點,然後新增多個property。配置完成之後使用${property_name}就可以在專案中引用了。正如下面的一個配置檔案中PatternLayout這樣。

屬性可以在配置檔案中引用,也可以直接替代或傳入潛在的元件,屬性在這些元件中能夠動態解析。屬性可以是配置檔案,系統屬性,環境變數,執行緒上下文對映以及事件中的資料中定義的值。使用者可以通過增加自己的Lookup外掛來定製自己的屬性。

3.7 其他新增的功能
3.5.1 自定義日誌級別
Log4J 2支援自定義日誌級別。可以在程式碼或配置中定義自定義日誌級別。使用 Level.forName()方法在程式碼中定義自定義日誌級別,如下圖所示:

在配置檔案中,可以使用標籤進行定義:

3.5.2 自定義外掛
Log4j 2使用外掛系統,不需要對Log4j進行任何更改,就能非常容易新增新的Appenders, Filters, Layouts, Lookups, 和Pattern Converters來擴充套件框架。所有可以配置的元件都以Log4j外掛的形式來定義。 Log4j自動識別預定義的外掛,如果在配置中引用到這些外掛,Log4j就自動載入使。

然後再配置檔案中進行引用:

三 效能分析對比
接下來對三種日誌log4j 1.x、log4j 2.x 和logback的效能進行對比:
測試環境:Lo4j1 1.2.17,Log4j 2.8.2,LockBack:1.1.7, JDk:1.8.0_131,Win7
logger 50 threads/500000條資料 50 threads/1000000條資料
Lo4j1:Synchronous 1108ms 2338ms
Logback: Synchronous 2733ms 5360ms
Lo4j2:Synchronous 1307ms 2449ms
Log4j1: Async Appender 954ms 1903ms
Logback: Async Appender 1765ms 3562ms
Log4j2:Logger syn/async 248ms 400ms
Log4j2:Logger all async 15ms 19ms

綜合測試資料對比可知:log4j2的非同步模式表現了絕對的效能優勢,優勢主要得益於Disruptor框架的使用,一個無鎖的執行緒間通訊庫代替了原來的佇列。
對於更加詳細的效能對比,如下圖所示,這是官網上的效能測試:
下面是Log4j 2.x與其他日誌記錄包的非同步吞吐量比較:

以下表格是在JDK1.7.0_06的Solaris 10(64位)上,啟用了超執行緒(4個虛擬核心)的4核Xeon X5570雙CPU @ 2.93Ghz:

下面的圖表將基於ArrayBlockingQueue的asynchronous appenders的 Logback 1.1.7、Log4j 1.2.17和Log4j 2.6響應時間延遲的對比。在每秒128,000個訊息的工作負載下,使用16個執行緒(每個以每秒8,000個訊息的速率記錄),我們看到Logback 1.1.7,Log4j 1.2.17遇到的延遲尖峰大於Log4j 2的數量級。

綜上可知,Log4j 2.x 不論在高併發和低延遲上都表現出來更加有利的優勢。
三 升級建議
1 公司現狀
目前在採用的是Log4j 1.2.17和slf4j 1.7.6的組合,主系統採用的是Logback 1.1.7和slf4j 1.7.6。系統中使用Log4j 1.2.17和slf4j 1.7.6相混合。主站系統同時使用Log4j1.x、JDK自帶的Logging和Logback。比較混亂,如果想升級到Log4j2.8.2,需要橋接器和介面卡進行轉換。
2 版本選擇
目前官網最新版本是Log4j 2.8.2,建議使用最新的版本,下面表格列舉了Log4j 2.8.x和2.7.x的主要修訂的一些bug。詳細的修改日誌見http://logging.apache.org/log4j/2.x/changes-report.html
以下列出的修復主要是針對系統中可能會涉及的功能的修復:
版本 解決的問題
2.8.x 0.修正了AsyncLogger無法解析配置屬性的錯誤
1.當安全管理器存在時,Log4j 2.8可能會丟失異常。
2.當LogEvent.getLoggerName()在KafkaAppender中返回null時處理。
3. 當LogEvent.getLoggerName()在LoggerNameLevelRewritePolicy中返回null時處理。
4. 修復%替換轉換器文件中的錯字。
5. 當找不到log4j 2配置檔案時,改進了錯誤訊息。
6. 使用syncSend = false時傳送到Kafka時報告錯誤。
7. 修復了屬性Util :: getCharsetProperty中導致ConsoleAppender的UnsupportedCharsetException異常。
8. RollingFileAppender現在支援省略檔名並直接寫入檔案.
9. 改進LogEvent序列化以處理不可序列化的訊息,並在需要的類丟失時進行反序列化。
10. 將LMAX Disruptor從3.3.5更新為3.3.6。
2.7.x 0. 關閉期間使用JUL日誌記錄時修復了ClassCastException。
1. RollingFileAppender immediateFlush預設值應為true,而不是false。
2. 修復由日誌引數物件的toString()方法巢狀日誌觸發的亂碼日誌訊息。
3. Log4j執行緒不再在Tomcat關機時洩漏。
4. 支援將配置中指定的屬性值作為值屬性以及元素。
5. 使用非同步日誌記錄和擴充套件堆疊跟蹤模式時固定的類載入程式死鎖。
6. 在配置中宣告的屬性現在可以在元素體中或名為“value”的屬性中使用。
7. RollingFileAppender、FileAppender現在可以按需建立檔案。
8. 允許RollingFileAppender使用預設模式佈局。
9.LMAX Disruptor從3.3.4更新到3.3.5。
10. Kafka客戶端從0.10.0.0更新到0.10.0.1。

3 升級要求
Apache Log4j 2與以前的版本不相容。升級到專案中的Log4j 2時,請注意以下幾點:
①Log4j 2.4及更高版本需要Java 7,版本2.0-alpha1至2.3所需的Java 6。
②XML配置已被簡化,與Log4j 1.x不相容。
③通過屬性檔案配置從2.4版本支援,但與Log4j 1.x不相容。
④支援通過JSON或YAML進行配置,但這些格式需要額外的執行時依賴關係。
⑤雖然Log4j 2與Log4j不直接相容1.xa相容性橋已經提供了減少編碼變化的需要。
在投顧系統中,使用的是Log4j 1.2.17和slf4j 1.7.6的組合,如果升級的話需要進行以下pom檔案中的替換:
注意:由於Log4j 2與Log4j 1.x的配置檔案比相容,Properties檔案中很多語法發生了變化。需要重寫Log4j 2的配置檔案,下圖是新舊配置的簡單對比:

同時由於Spring最新的版本仍然對Log4j 2.x 的配置檔案無法解析(雖然介面文件上支援Log4j 2.x,但是原始碼上卻仍然使用的是Log4j 1.x的工具進行解析),所以對於配置檔案的初始化,需要放在web.xml中,這樣就會導致spring的單元測試無法載入屬性配置檔案。有兩種解決方案:
第一種:Log的配置檔案初始化載入放在web.xml中。如下圖所示:

第二種方案是需要單元測試的單元中程式設計載入Log4j 2.x的配置檔案,如下程式碼所示:

這樣單元測試才能使用到Log4j 2.x 配置。

對於POM檔案的修改,需要去掉Log4j 1和Logback的依賴包,同時加上Log4j 2.x的依賴包,其中Log4j-web用於屬性檔案的載入和監聽,disruptor用於非同步記錄日誌使用。如下所示:

同時, 如果在Log4j 1.x 中使用Logger,而Log4j 1.x使用的是LogManager,如果沒有使用sslf4j介面就需要手動替換Logger->LogManager或者替換成Logger->LoggerFactory。
建議工程裡面全部修改成利用日誌門面使用日誌。