[日誌]Java日誌性能那些事

在任何系統中，日誌都是很是重要的組成部分，它是反映系統運行狀況的重要依據，也是排查問題時的必要線索。絕大多數人都承認日誌的重要性，可是又有多少人仔細想過該怎麼打日誌，日誌對性能的影響究竟有多大呢？今天就讓咱們來聊聊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倍多。

看了上面這麼多的數據，不知您是否以爲本身的日誌有很多改進的餘地，您尚未把系統優化到極致，亦或者您還有其餘日誌優化的方法，不妨分享給你們。