小小的日誌,大大的坑

京東雲開發者發表於2023-12-12

1. 背景

壓測過程中最佳化執行緒池以後單機qps存在效能瓶頸,最佳化過程中發現預設執行緒池及日誌對效能存在嚴重的影響所以引發了一系列對日誌最佳化的整理

2.哪些場景可能導致效能問題

在任何系統中,日誌都是非常重要的組成部分,它是反映系統執行情況的重要依據,也是排查問題時的必要線索。絕大多數人都認可日誌的重要性,但是又有哪些場景可能導致效能問題?今天就讓我們來聊聊Java日誌效能那些事。

2.1 不合理的書寫方法

如上3種寫法,我相信大家或多或少都在專案程式碼中看到過,那麼他們之前有區別呢,會對效能造成什麼影響? 如果此時關閉 DEBUG 日誌級別,差異就出現了

格式1 依然還是要執行字串拼接,即使它不輸出日誌,屬於浪費。

格式2 的缺點就是引數會提前做JSON序列化也產生效能損耗。

所以推薦格式3,新增日誌開關,只有在執行時才會動態的拼接,關閉相應日誌級別後,不會有效能損耗。

2.2 不合理的日誌

儘量多的日誌,能夠把使用者的請求串起來,更容易斷定出問題的程式碼位置。由於當前分散式系統,且業務龐雜,任何日誌的缺失對於程式設計師定位問題都是極大的障礙。所以要合理的列印日誌,設定合理的日誌級別

2.3 日誌輸出格式

位置資訊 官網稱作 Location Information,含義是當前這行日誌是哪個類的哪個方法哪一行列印的。

可配置的模式有很多,具體見官網
https://logging.apache.org/log4j/2.x/manual/layouts.html#Patterns

這裡只說和位置相關的 %C or %class, %F or %file, %l or %location, %L or %line, %M or %method。

官網這幾個模式的說明中也都反覆強調了會影響效能。同時也給出了具體的效能資料,比常用的同步 logger 慢 1.3 ~ 5 倍。如果在非同步 logger 中使用位置資訊,將會慢 30 ~ 100 倍。

3. 如何儘量避免日誌對效能產生影響

3.1 日誌級別動態調整

用好DEBUG級別!專案程式碼需要列印大量 INFO級別日誌,以支援問題定位及測試排查等。但這些大量的 INFO日誌對生產環境是無效的,大量的日誌會吃掉 CPU 效能,此時需要能動態調整日誌級別,既滿足可隨時檢視 INFO日誌,又能滿足不需要時可動態關閉,不影響服務效能需要。

3.2 不打無用日誌

日誌內容,能少就少,不在迴圈中打,大 list 簡化,不打無用內容。

明顯知道的異常棧不要列印(比如自定義異常捕獲後直接列印異常資訊即可)

3.3 避免字串拼接

避免使用字串連線:在日誌記錄中,字串連線是一項較為昂貴的操作,特別是在迴圈中使用。每次進行字串連線都會產生一個新的字串物件,浪費了記憶體和時間。應優先考慮使用佔位符的形式,如使用slf4j庫中的"{}",然後傳入引數,並避免使用字串連線。

3.4 新增日誌開關

按需新增日誌開關減少不必要的效能損耗,例如JSON序列化及字串拼接等等。(若無相關操作則不需要新增日誌開關,反而存在一堆廢程式碼)

3.5 調整日誌輸出格式

影響效能的位置資訊按需選擇減少效能損耗

3.6 日誌非同步列印(謹慎選擇)

同步列印日誌磁碟 I/O 成為瓶頸,導致大量執行緒 Block,非同步缺可能產生日誌丟失。

4. 最佳化成果

4.1最佳化前(單機80qps..效能已經不可用 耗時高達1500+ms):

4.2最佳化後(單機200qps tp999穩定在575ms):

作者:京東零售 王軍

來源:京東雲開發者社群 轉載請註明來源

相關文章