Java日志性能那些事

在任何系統(tǒng)中症虑,日志都是非常重要的組成部分缩歪,它是反映系統(tǒng)運行情況的重要依據(jù),也是排查問題時的必要線索谍憔。絕大多數(shù)人都認(rèn)可日志的重要性匪蝙,但是又有多少人仔細(xì)想過該怎么打日志,日志對性能的影響究竟有多大呢习贫?今天就讓我們來聊聊Java日志性能那些事逛球。

說到Java日志,大家肯定都會說要選擇合理的日志級別苫昌、合理控制日志內(nèi)容颤绕,但是這僅是萬里長征第一步……哪怕一些DEBUG級別的日志在生產(chǎn)環(huán)境中不會輸出到文件中,也可能帶來不小的開銷祟身。我們撇開判斷和方法調(diào)用的開銷奥务,在Log4J 2.x的性能文檔中有這樣一組對比:

logger.debug("Entry number: " + i + " is " +? String.valueOf(entry[i]));

logger.debug("Entry number: {} is {}", i, entry[i]);

上面兩條語句在日志輸出上的效果是一樣的,但是在關(guān)閉DEBUG日志時袜硫,它們的開銷就不一樣了氯葬,主要的影響在于字符串轉(zhuǎn)換和字符串拼接上,無論是否生效婉陷,前者都會將變量轉(zhuǎn)換為字符串并進行拼接帚称,而后者則只會在需要時執(zhí)行這些操作。Log4J官方的測試結(jié)論是兩者在性能上能相差兩個數(shù)量級秽澳。試想一下闯睹,如果某個對象的toString()方法里用了ToStringBuilder來反射輸出幾十個屬性時,這時能省下多少資源担神。

因此瞻坝,某些仍在使用Log4J 1.x或Apache Commons Logging(它們不支持{}模板的寫法)的公司都會有相應(yīng)的編碼規(guī)范,要求在一定級別的日志(比如DEBUG和INFO)輸出前增加判斷:

if (logger.isDebugEnabled()) {

logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i]));

}

除了日志級別和日志消息杏瞻,通常在日志中還會包含一些其他信息,比如日期衙荐、線程名捞挥、類信息、MDC變量等等忧吟,根據(jù)Takipi的測試砌函,如果在日志中加入class,性能會急劇下降,比起LogBack的默認(rèn)配置讹俊,吞吐量的降幅在6成左右垦沉。如果一定要打印類信息,可以考慮用類名來命名Logger仍劈。

在分布式系統(tǒng)中厕倍,一個請求可能會經(jīng)過多個不同的子系統(tǒng),這時最好生成一個UUID附在請求中贩疙,每個子系統(tǒng)在打印日志時都將該UUID放在MDC里讹弯,便于后續(xù)查詢相關(guān)的日志≌饨Γ《The Ultimate Guide: 5 Methods For Debugging Production Servers At Scale》一文中就如何在生產(chǎn)環(huán)境中進行調(diào)試給出了不少建議组民,當(dāng)中好幾條是關(guān)于日志的,這就是其中之一悲靴。另一條建議是記錄下所有未被捕獲的日志臭胜,其實拋出異常有開銷,記錄異常同樣會帶來一定的開銷癞尚,主要原因是Throwable類的fillInStackTrace方法默認(rèn)是同步的:

public synchronized native Throwable fillInStackTrace();

一般使用logger.error都會打出異常的堆棧耸三,如果對吞吐量有一定要求,在情況運行時可以考慮覆蓋該方法否纬,去掉synchronized native吕晌,直接返回實例本身。

聊完日志內(nèi)容临燃,再來看看Appender睛驳。在Java中,說起IO操作大家都會想起NIO膜廊,到了JDK 7還有了AIO乏沸,至少都知道讀寫加個Buffer,日志也是如此爪瓜,同步寫的Appender在高并發(fā)大流量的系統(tǒng)里多少有些力不從心蹬跃,這時就該使用AsyncAppender了,同樣是使用LogBack:

在10線程并發(fā)下铆铆,輸出200字符的INFO日志蝶缀,AsyncAppender的吞吐量最高能是FileAppender的3.7倍。在不丟失日志的情況下薄货,同樣使用AsyncAppender翁都,隊列長度對性能也會有一定影響。

如果使用Log4J 2.x谅猾,那么除了有AsyncAppender柄慰,還可以考慮性能更高的異步Logger鳍悠,由于底層用了Disruptor,沒有鎖的開銷坐搔,性能更為驚人藏研。根據(jù)Log4J 2.x的官方測試,同樣使用Log4J 2.x:

64線程下概行,異步Logger比異步Appender快12倍蠢挡,比同步Logger快68倍。

同樣是異步占锯,不同的庫之間也會有差異:

同等硬件環(huán)境下袒哥,Log4J 2.x全部使用異步Logger會比LogBack的AsyncAppender快12倍,比Log4J 1.x的異步Appender快19倍消略。

Log4J 2.x的異步Logger性能強悍堡称,但也有不同的聲音,覺得這只是個看上去很優(yōu)雅艺演,只能當(dāng)成一個玩具却紧。關(guān)于這個問題,還是留給讀者自己來思考吧胎撤。

如果一定要用同步的Appender晓殊,那么可以考慮使用ConsoleAppender,然后將STDOUT重定向到文件里伤提,這樣大約也能有10%左右的性能提升巫俺。

大部分生產(chǎn)系統(tǒng)都是集群部署,對于分布在不同服務(wù)器上的日志肿男,用Logstash之類的工具收集就好了介汹。很多時候還會在單機上部署多實例以便充分利用服務(wù)器資源,這時千萬不要貪圖日志監(jiān)控或者日志查詢方便舶沛,將多個實例的日志寫到同一個日志文件中嘹承,雖然LogBack提供了prudent模式,能夠讓多個JVM往同一個文件里寫日志如庭,但此種方式對性能同樣也有影響叹卷,大約會使性能降低10%。

如果對同一個日志文件有大量的寫需求坪它,可以考慮拆分日志到不同的文件骤竹,做法之一是添加多個Appender,同時修改代碼往毡,不同的情況使用不同Logger瘤载;LogBack提供了SiftingAppender,可以直接根據(jù)MDC的內(nèi)容拆分日志卖擅,Jetty的教程中就有根據(jù)host來拆分日志的范例,而根據(jù)Takipi的測試,SiftingAppender的性能會隨著拆分文件數(shù)的增長一同提升惩阶,當(dāng)拆分為4個文件時挎狸,10并發(fā)下SiftingAppender的吞吐量約是FileAppender的3倍多。

看了上面這么多的數(shù)據(jù)断楷,不知您是否覺得自己的日志有不少改進的余地锨匆,您還沒有把系統(tǒng)優(yōu)化到極致,亦或者您還有其他日志優(yōu)化的方法冬筒,不妨分享給大家恐锣。

最后編輯于
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
  • 序言:七十年代末,一起剝皮案震驚了整個濱河市舞痰,隨后出現(xiàn)的幾起案子土榴,更是在濱河造成了極大的恐慌,老刑警劉巖响牛,帶你破解...
    沈念sama閱讀 217,826評論 6 506
  • 序言:濱河連續(xù)發(fā)生了三起死亡事件玷禽,死亡現(xiàn)場離奇詭異,居然都是意外死亡呀打,警方通過查閱死者的電腦和手機矢赁,發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 92,968評論 3 395
  • 文/潘曉璐 我一進店門,熙熙樓的掌柜王于貴愁眉苦臉地迎上來贬丛,“玉大人撩银,你說我怎么就攤上這事〔蜚荆” “怎么了额获?”我有些...
    開封第一講書人閱讀 164,234評論 0 354
  • 文/不壞的土叔 我叫張陵,是天一觀的道長焕阿。 經(jīng)常有香客問我咪啡,道長,這世上最難降的妖魔是什么暮屡? 我笑而不...
    開封第一講書人閱讀 58,562評論 1 293
  • 正文 為了忘掉前任撤摸,我火速辦了婚禮,結(jié)果婚禮上褒纲,老公的妹妹穿的比我還像新娘准夷。我一直安慰自己,他們只是感情好莺掠,可當(dāng)我...
    茶點故事閱讀 67,611評論 6 392
  • 文/花漫 我一把揭開白布衫嵌。 她就那樣靜靜地躺著,像睡著了一般彻秆。 火紅的嫁衣襯著肌膚如雪楔绞。 梳的紋絲不亂的頭發(fā)上结闸,一...
    開封第一講書人閱讀 51,482評論 1 302
  • 那天,我揣著相機與錄音酒朵,去河邊找鬼桦锄。 笑死,一個胖子當(dāng)著我的面吹牛蔫耽,可吹牛的內(nèi)容都是我干的结耀。 我是一名探鬼主播,決...
    沈念sama閱讀 40,271評論 3 418
  • 文/蒼蘭香墨 我猛地睜開眼匙铡,長吁一口氣:“原來是場噩夢啊……” “哼图甜!你這毒婦竟也來了?” 一聲冷哼從身側(cè)響起鳖眼,我...
    開封第一講書人閱讀 39,166評論 0 276
  • 序言:老撾萬榮一對情侶失蹤黑毅,失蹤者是張志新(化名)和其女友劉穎,沒想到半個月后具帮,有當(dāng)?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體博肋,經(jīng)...
    沈念sama閱讀 45,608評論 1 314
  • 正文 獨居荒郊野嶺守林人離奇死亡,尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點故事閱讀 37,814評論 3 336
  • 正文 我和宋清朗相戀三年蜂厅,在試婚紗的時候發(fā)現(xiàn)自己被綠了匪凡。 大學(xué)時的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片。...
    茶點故事閱讀 39,926評論 1 348
  • 序言:一個原本活蹦亂跳的男人離奇死亡掘猿,死狀恐怖病游,靈堂內(nèi)的尸體忽然破棺而出,到底是詐尸還是另有隱情稠通,我是刑警寧澤衬衬,帶...
    沈念sama閱讀 35,644評論 5 346
  • 正文 年R本政府宣布,位于F島的核電站改橘,受9級特大地震影響滋尉,放射性物質(zhì)發(fā)生泄漏。R本人自食惡果不足惜飞主,卻給世界環(huán)境...
    茶點故事閱讀 41,249評論 3 329
  • 文/蒙蒙 一狮惜、第九天 我趴在偏房一處隱蔽的房頂上張望。 院中可真熱鬧碌识,春花似錦碾篡、人聲如沸。這莊子的主人今日做“春日...
    開封第一講書人閱讀 31,866評論 0 22
  • 文/蒼蘭香墨 我抬頭看了看天上的太陽。三九已至魁瞪,卻和暖如春穆律,著一層夾襖步出監(jiān)牢的瞬間惠呼,已是汗流浹背。 一陣腳步聲響...
    開封第一講書人閱讀 32,991評論 1 269
  • 我被黑心中介騙來泰國打工峦耘, 沒想到剛下飛機就差點兒被人妖公主榨干…… 1. 我叫王不留罢杉,地道東北人。 一個月前我還...
    沈念sama閱讀 48,063評論 3 370
  • 正文 我出身青樓贡歧,卻偏偏與公主長得像,于是被迫代替她去往敵國和親赋秀。 傳聞我的和親對象是個殘疾皇子利朵,可洞房花燭夜當(dāng)晚...
    茶點故事閱讀 44,871評論 2 354

推薦閱讀更多精彩內(nèi)容

  • 在任何系統(tǒng)中,日志都是非常重要的組成部分猎莲,它是反映系統(tǒng)運行情況的重要依據(jù)绍弟,也是排查問題時的必要線索。絕大多數(shù)人都認(rèn)...
    流浪java閱讀 517評論 0 4
  • 在應(yīng)用程序中添加日志記錄總的來說基于三個目的:監(jiān)視代碼中變量的變化情況著洼,周期性的記錄到文件中供其他應(yīng)用進行統(tǒng)計分析...
    時待吾閱讀 5,046評論 1 13
  • 在應(yīng)用程序中添加日志記錄總的來說基于三個目的:監(jiān)視代碼中變量的變化情況樟遣,周期性的記錄到文件中供其他應(yīng)用進行統(tǒng)計分析...
    時待吾閱讀 4,985評論 0 6
  • log4j 1.1 簡介 Log4j是一個由Java編寫可靠、靈活的日志框架身笤,是Apache旗下的一個開源項目豹悬;現(xiàn)...
    賈博巖閱讀 7,904評論 1 32
  • from:https://www.cnblogs.com/ITtangtang/p/3926665.html一、L...
    enshunyan閱讀 3,290評論 0 0