小小的紀錄檔,大大的坑

2023-12-12 12:01:16

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

這裡只說和位置相關的 %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):

作者:京東零售 王軍

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