Log4j2的性能為什麼這麼好?

原文:https://www.jianshu.com/p/359b14067b9e;

原創:詹嵩 某公司架構部中間件架構師;

校對:程超 某公司架構部中間件負責人


Log4j2的性能為什麼這麼好?



一、logback和log4j2壓測比較

  • logback壓測數據
  • log4j2壓測數據


1、logback壓測數據

logback壓測數據,50個線程,500萬條日誌寫入時間。

logback:messageSize = 5000000,threadSize = 50,costTime = 27383ms
logback:messageSize = 5000000,threadSize = 50,costTime = 26391ms
logback:messageSize = 5000000,threadSize = 50,costTime = 25373ms
logback:messageSize = 5000000,threadSize = 50,costTime = 25636ms
logback:messageSize = 5000000,threadSize = 50,costTime = 25525ms
logback:messageSize = 5000000,threadSize = 50,costTime = 25775ms
logback:messageSize = 5000000,threadSize = 50,costTime = 27056ms
logback:messageSize = 5000000,threadSize = 50,costTime = 25741ms
logback:messageSize = 5000000,threadSize = 50,costTime = 25707ms
logback:messageSize = 5000000,threadSize = 50,costTime = 25619ms

說明:

這個是logback日誌的壓測數據,在開發機(雙核四線程),高配開發機(四核八線程)和服務器(32核)壓測的效率都差不多,而且線程開多的時候,性能反而有下降,壓測數據如下:

logback:messageSize = 5000000,threadSize = 100,costTime = 33376ms


這個是在32核機器上壓測的平均值,高於開發機。

2、log4j2壓測數據

log4j2壓測數據,因測試數據會佔用一些篇幅,這裡僅取中位數,但上下差距並不大

log4j2:messageSize = 5000000,threadSize = 100,costTime = 15509ms ---開發機 
log4j2:messageSize = 5000000,threadSize = 100,costTime = 5042ms ---高配開發機
log4j2:messageSize = 5000000,threadSize = 100,costTime = 3832ms ---服務器

本次壓測,基本上與log4j2官網數據吻合,經過驗證異步日誌確實可以極大的提高IO效率

下圖為同步、異步、只異步appender的性能對比

Log4j2的性能為什麼這麼好?

Async loggers have much higher throughput than sync loggers.

和其他日誌框架的對比:

Log4j2的性能為什麼這麼好?

Async loggers have the highest throughput.

從本次壓測中,也得知確實在同步日誌寫到一定程度下,會大大的影響服務器的吞吐率,各位同學可以根據自己項目的情況,做日誌上的優化。

下圖為併發量大時,日誌框架對系統吞吐率產生的影響,這裡看logback和log4j確實影響很大,但實際情況中,感受到的要遠遠小於此圖。

Log4j2的性能為什麼這麼好?

二、壓測配置

log4j2的效率可以在多線程時,在線程數量大的情況下,超過logback10倍左右!500萬數據大概0.25G,只需3秒左右就可以寫進磁盤。

在配置上,首先第一條建議是如果做異步,那麼所有的日誌都是異步寫,這樣的性能指數的增長是量級的。當然也可以混合部署,但是性能影響就沒有全部異步這麼明顯。

配置上,優化一定的屬性,對性能也有一定的影響。

log4j2本身提供了20多種appender供使用者選用,但一般開發中採用的就是RollingRandomAccessFile,該組件有多個屬性配置,常用的做一下說明(其他配置對性能意義不大,有興趣的同學可自己去官網查看)

Log4j2的性能為什麼這麼好?

一般採用默認值,除非系統寫日誌的IO影響了主線程的運行,可以調大該配置。

本次壓測採用的日誌配置

Log4j2的性能為什麼這麼好?

在asyncRoot中可以添加includeLocation="true"屬性,該屬性如果為true,可以攜帶類名和行號等信息,但是抽取這些信息,會有一些性能損耗

log4j2改版以後,組件和功能極大豐富,有興趣的同學可以去官網http://logging.apache.org/log4j/2.x/manual/index.html或找我來一起交流。

三、disruptor隊列

查看底層代碼,log4j2之所以能在異步寫日誌時性能提高這麼多,離不開優秀的mq組件disruptor。

目前使用該隊列的知名軟件包括但不限於Apache Storm、Camel、Log4j 2。

由於時間有限,本篇著重講解底層隊列的實現,因為這個對性能的影響是最大的。

以此圖為例:

Log4j2的性能為什麼這麼好?

Async loggers have much higher throughput than sync loggers.

同步性能最差,異步全局異步的性能接近異步appender的10倍,同樣是異步實現的,為何性能有如此大的差距?

去看源碼:

Log4j2的性能為什麼這麼好?


Log4j2的性能為什麼這麼好?


以上是異步Appender的實現,可以看到,內部內置了一個BlockingQueue隊列,具體實現採用了ArrayBlockingQueue

Log4j2的性能為什麼這麼好?

接著是全局異步loggers的實現方式,可見內部的隊列使用的是disruptor。

性能上的優劣,絕大部分原因都是數據模型的問題,往下我們分析一下BlockingQueue和disruptor的實現方式,由於篇幅有限,從JDK源碼來看:

1、ArrayBlockingQueue

Log4j2的性能為什麼這麼好?


Log4j2的性能為什麼這麼好?

可以看到ArrayBlockingQueue採用的是加鎖的方式來處理線程安全問題的。

加鎖的問題,雖然歷代JDK一直投入大量的精力去解決問題,比如優化Sync關鍵字的實現方式、添加讀寫鎖等,但是由於結構特性的問題,一直無法從根本上解決性能開銷問題。

題外話 _ 除了鎖的問題,還牽涉到底層CPU在計算時讀取內存數據的問題。

舉個例子:當你遍歷一個數組時(數組在CPU計算時,是簡單數據結構),你讀取到第一個元素時,其他元素也會相應的放入1級緩存(距離CPU最近),所以你遍歷數據的方式是最快的,這就是簡單數據結構的優勢。

但是如果你在操作一個Queue時,一般會涉及幾個變量,這裡以ArrayBlockingQueue為例:

Log4j2的性能為什麼這麼好?

這裡有三個變量,分別代表了下一個要出的元素下標,要進的元素下標和長度

當然,這幾個簡單類型是非常容易放入1級緩存並進行高速計算的,但是問題是,這個Queue是一個生產者和消費者的模型,牽涉到兩端操作,於是當生產者寫入元素時,takeIndex和putIndex數值發生改變,消費者在消費時要拿的takeIndex也跟著改變,這時就需要去主存中重新去取takeIndex,而無法利用1級緩存進行高速計算。

以上大致解釋了ArrayBlockingQueue的性能劣勢,接下來就看disputor如果解決這些問題。

2、Disputor

引入官網的一段話(首先要明白背景和訴求):

Log4j2的性能為什麼這麼好?

這裡的表述和我們的目標一致,都是要解決鎖和緩存缺失帶來的性能開銷問題。

引用幾張官網的截圖(風格還比較有趣):

Log4j2的性能為什麼這麼好?

https://www.slideshare.net/trishagee/introduction-to-the-disruptor?from=new_upload_email 這是該PPT的地址,有興趣的同學可以關注下。

他們採用了環形數據結構來解決這個問題(他們稱之為魔法圓環,或魔法圓圈之類的),此種數據結構的有點是,不需要記錄額外的下標,直接由JNI返回可以操作的地址,然後當多線程併發讀寫的時候,使用的也是cas方式。

這樣,不能使用1級緩存和加鎖操作的問題就解決了(關於CAS大家可自行谷歌,有非常多的文章來介紹)。

由於篇幅和經歷有限,本次分享先寫到這裡,如果之後對disruptor有需要的話,可以再次深入研究。

Log4j2的性能為什麼這麼好?


分享到:


相關文章: