在任何系統中,日志都是非常重要的組成部分,它是反映系統運行情況的重要依據,也是排查問題時的必要線索。絕大多數人都認可日志的重要性,但是又有多少人仔細想過該怎麼打日志,日志對性能的影響究竟有多大呢?今天就讓我們來聊聊Java日志性能那些事。
說到Java日志,大家肯定都會說要選擇合理的日志級別、合理控制日志內容,但是這僅是萬裡長征第一步……哪怕一些DEBUG
級別的日志在生產環境中不會輸出到文件中,也可能帶來不小的開銷。我們撇開判斷和方法調用的開銷,在Log4J 2.x的性能文檔中有這樣一組對比:
logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i])); logger.debug("Entry number: {} is {}", i, entry[i]);
上面兩條語句在日志輸出上的效果是一樣的,但是在關閉DEBUG
日志時,它們的開銷就不一樣了,主要的影響在於字符串轉換和字符串拼接上,無論是否生效,前者都會將變量轉換為字符串並進行拼接,而後者則只會在需要時執行這些操作。Log4J官方的測試結論是兩者在性能上能相差兩個數量級。試想一下,如果某個對象的toString()
方法裡用了ToStringBuilder
來反射輸出幾十個屬性時,這時能省下多少資源。
因此,某些仍在使用Log4J 1.x或Apache Commons Logging(它們不支持{}
模板的寫法)的公司都會有相應的編碼規范,要求在一定級別的日志(比如DEBUG
和INFO
)輸出前增加判斷:
if (logger.isDebugEnabled()) { logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i])); }
除了日志級別和日志消息,通常在日志中還會包含一些其他信息,比如日期、線程名、類信息、MDC變量等等,根據Takipi的測試,如果在日志中加入class
,性能會急劇下降,比起LogBack的默認配置,吞吐量的降幅在6成左右。如果一定要打印類信息,可以考慮用類名來命名Logger
。
在分布式系統中,一個請求可能會經過多個不同的子系統,這時最好生成一個UUID附在請求中,每個子系統在打印日志時都將該UUID放在MDC裡,便於後續查詢相關的日志。《The Ultimate Guide: 5 Methods For Debugging Production Servers At Scale》一文中就如何在生產環境中進行調試給出了不少建議,當中好幾條是關於日志的,這就是其中之一。另一條建議是記錄下所有未被捕獲的日志,其實拋出異常有開銷,記錄異常同樣會帶來一定的開銷,主要原因是Throwable
類的fillInStackTrace
方法默認是同步的:
public synchronized native Throwable fillInStackTrace();
一般使用logger.error
都會打出異常的堆棧,如果對吞吐量有一定要求,在情況運行時可以考慮覆蓋該方法,去掉synchronized native
,直接返回實例本身。
聊完日志內容,再來看看Appender
。在Java中,說起IO操作大家都會想起NIO,到了JDK 7還有了AIO,至少都知道讀寫加個Buffer
,日志也是如此,同步寫的Appender
在高並發大流量的系統裡多少有些力不從心,這時就該使用AsyncAppender
了,同樣是使用LogBack:
在10線程並發下,輸出200字符的
INFO
日志,AsyncAppender
的吞吐量最高能是FileAppender
的3.7倍。在不丟失日志的情況下,同樣使用AsyncAppender
,隊列長度對性能也會有一定影響。
如果使用Log4J 2.x,那麼除了有AsyncAppender
,還可以考慮性能更高的異步Logger
,由於底層用了Disruptor,沒有鎖的開銷,性能更為驚人。根據Log4J 2.x的官方測試,同樣使用Log4J 2.x:
64線程下,異步
Logger
比異步Appender
快12倍,比同步Logger
快68倍。
同樣是異步,不同的庫之間也會有差異:
同等硬件環境下,Log4J 2.x全部使用異步
Logger
會比LogBack的AsyncAppender
快12倍,比Log4J 1.x的異步Appender
快19倍。
(點擊放大圖像)
Log4J 2.x的異步Logger
性能強悍,但也有不同的聲音,覺得這只是個看上去很優雅,只能當成一個玩具。關於這個問題,還是留給讀者自己來思考吧。
如果一定要用同步的Appender
,那麼可以考慮使用ConsoleAppender
,然後將STDOUT
重定向到文件裡,這樣大約也能有10%左右的性能提升。
大部分生產系統都是集群部署,對於分布在不同服務器上的日志,用Logstash之類的工具收集就好了。很多時候還會在單機上部署多實例以便充分利用服務器資源,這時千萬不要貪圖日志監控或者日志查詢方便,將多個實例的日志寫到同一個日志文件中,雖然LogBack提供了prudent
模式,能夠讓多個JVM往同一個文件裡寫日志,但此種方式對性能同樣也有影響,大約會使性能降低10%。
如果對同一個日志文件有大量的寫需求,可以考慮拆分日志到不同的文件,做法之一是添加多個Appender
,同時修改代碼,不同的情況使用不同Logger
;LogBack提供了SiftingAppender
,可以直接根據MDC的內容拆分日志,Jetty的教程中就有根據host
來拆分日志的范例,而根據Takipi的測試,SiftingAppender
的性能會隨著拆分文件數的增長一同提升,當拆分為4個文件時,10並發下SiftingAppender
的吞吐量約是FileAppender
的3倍多。
看了上面這麼多的數據,不知您是否覺得自己的日志有不少改進的余地,您還沒有把系統優化到極致,亦或者您還有其他日志優化的方法,不妨分享給大家。