為什麼我建議線上高併發量的日誌輸出的時候不能帶有程式碼位置

乾貨滿滿張雜湊發表於2022-03-26

個人創作公約：本人宣告創作的所有文章皆為自己原創，如果有參考任何文章的地方，會標註出來，如果有疏漏，歡迎大家批判。如果大家發現網上有抄襲本文章的，歡迎舉報，並且積極向這個 github 倉庫 提交 issue，謝謝支援~

本文是“為什麼我建議”系列第二篇，本系列中會針對一些在高併發場景下，我對於組內後臺開發的一些開發建議以及開發規範的要求進行說明和分析解讀，相信能讓各位在面對高併發業務的時候避開一些坑。
往期回顧：

在業務一開始上線的時候，我們線上日誌級別是 INFO，並且在日誌內容中輸出了程式碼位置，格式例如：

2022-03-02 19:57:59.425  INFO [service-apiGateway,,] [35800] [main][org.springframework.cloud.gateway.route.RouteDefinitionRouteLocator:88]: Loaded RoutePredicateFactory [Query]

我們使用的日誌框架是 Log4j2，方式是非同步日誌，Log4j2 的 Disruptor 的 WaitStrategy 採用了比較平衡 CPU 佔用比較小的 Sleep，即配置了：AsyncLoggerConfig.WaitStrategy=Sleep。隨著業務的增長，我們發現經常有的例項 CPU 佔用非常之高（尤其是那種短時間內有大量日誌輸出的），我們 dump 了 JFR 進行進一步定位：

首先我們來看 GC，我們的 GC 演算法是 G1，主要通過 G1 Garbage Collection這個事件檢視：

image

發現 GC 全部為 Young GC，且耗時比較正常，頻率上也沒有什麼明顯異常。

接下來來看，CPU 佔用相關。直接看 Thread CPU Load 這個事件，看每個執行緒的 CPU 佔用情況。發現reactor-http-epoll執行緒池的執行緒，CPU 佔用很高，加在一起，接近了 100%。

image

這些執行緒是 reactor-netty 處理業務的執行緒，觀察其他例項，發現正常情況下，並不會有這麼高的 CPU 負載。那麼為啥會有這麼高的負載呢？通過 Thread Dump 來看一下執行緒堆疊有何發現.

通過檢視多個執行緒堆疊 dump，發現這些執行緒基本都處於 Runnable，並且執行的方法是原生方法，和StackWalker相關，例如（並且這個與 JFR 中採集的 Method Runnable 事件中佔比最高的吻合，可以基本確認這個執行緒的 CPU 主要消耗在這個堆疊當前對應的方法上）：
image

主要和這兩個原生方法有關：

  • java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk
  • java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames

並且需要注意微服務中執行緒堆疊會很深（150左右），對於響應式程式碼更是如此（可能會到300），主要是因為 servlet 與 filter 的設計是責任鏈模式，各個 filter 會不斷加入堆疊。響應式的程式碼就更是這樣了，一層套一層，各種拼接觀察點。上面列出的堆疊就是響應式的堆疊。

會到那兩個原生方法，其實這裡的程式碼是在做一件事，就是日誌中要輸出呼叫列印日誌方法的程式碼位置，包括類名，方法名，方法行數這些。在上面我給出的執行緒堆疊的例子中，呼叫列印日誌方法的程式碼位置資訊就是這一行：at com.xxx.apigateway.filter.AccessCheckFilter.filter(AccessCheckFilter.java:144)，這一行中，我們使用 log.info() 輸出了一些日誌。

可以看出，Log4j2 是通過獲取當前執行緒堆疊來獲取呼叫列印日誌方法的程式碼位置的。並且並不是堆疊中的棧頂就是呼叫列印日誌方法的程式碼位置，而是找到 log4j2 堆疊元素之後的第一個堆疊元素才是列印日誌方法的程式碼位置

Log4j2 中是如何獲取堆疊的

我們先來自己思考下如何實現：首先 Java 9 之前，獲取當前執行緒（我們這裡沒有要獲取其他執行緒的堆疊的情況，都是當前執行緒）的堆疊可以通過：

image
其中 Thread.currentThread().getStackTrace(); 的底層其實就是 new Exception().getStackTrace(); 所以其實本質是一樣的。

Java 9 之後，新增了新的 StackWalker 介面，結合 Stream 介面來更優雅的讀取堆疊，即：
image

我們先來看看 new Exception().getStackTrace(); 底層是如何獲取堆疊的：

javaClasses.cpp
image

然後是 StackWalker，其核心底層原始碼是：
image

可以看出，核心都是填充堆疊詳細資訊，區別是一個直接填充所有的，一個會減少填充堆疊資訊。填充堆疊資訊，主要訪問的其實就是 SymbolTable，StringTable 這些，因為我們要看到的是具體的類名方法名，而不是類的地址以及方法的地址，更不是類名的地址以及方法名的地址。那麼很明顯：通過 Exception 獲取堆疊對於 Symbol Table 以及 String Table 的訪問次數要比 StackWalker 的多，因為要填充的堆疊多。

我們接下來測試下，模擬在不同堆疊深度下，獲取程式碼執行會給原本的程式碼帶來多少效能衰減。

模擬兩種方式獲取呼叫列印日誌方法的程式碼位置，與不獲取程式碼位置會有多大效能差異

以下程式碼我參考的 Log4j2 官方程式碼的單元測試，首先是模擬某一呼叫深度的堆疊程式碼：

image
然後，編寫測試程式碼，對比純執行這個程式碼，以及加入獲取堆疊的程式碼的效能差異有多大。

image

執行：檢視結果：

image
從結果可以看出，獲取程式碼執行位置，也就是獲取堆疊，會造成比較大的效能損失。同時，這個效能損失，和堆疊填充相關。填充的堆疊越多，損失越大。可以從 StackWalker 的效能優於通過異常獲取堆疊，並且隨著堆疊深度增加差距越來越明顯看出來。

為何會慢？String::intern 帶來的效能衰減程度測試

這個效能衰減，從前面的對於底層 JVM 原始碼的分析，其實可以看出來是因為對於 StringTable 以及 SymbolTable 的訪問，我們來模擬下這個訪問，其實底層對於 StringTable 的訪問都是通過 String 的 intern 方法，即我們可以通過 String::intern 方法進行模擬測試，測試程式碼如下：
image

測試結果：
image

對比 StackWalkBenchmark.baseline 與 StackWalkBenchmark.toString 的結果，我們看出 bh.consume(time); 本身沒有什麼效能損失。但是通過將他們與 StackWalkBenchmark.intern 以及 StackWalkBenchmark.intern3 的結果對比，發現這個效能衰減，也是很嚴重的，並且訪問的越多，效能衰減越嚴重（類比前面獲取堆疊）。

結論與建議

由此，我們可以得出如下直觀的結論：

  1. 日誌中輸出程式碼行位置，Java 9 之前通過異常獲取堆疊，Java 9 之後通過 StackWalker
  2. 兩種方式都需要訪問 SymbolTable 以及 StringTable，StackWalker 可以通過減少要填充的堆疊來減少訪問量
  3. 兩種方式對於效能的衰減都是很嚴重的。

由此，我建議：對於微服務環境，尤其是響應式微服務環境，堆疊深度非常深，如果會輸出大量的日誌的話，這個日誌是不能帶有程式碼位置的，否則會造成嚴重的效能衰減。

我們在關閉輸出程式碼行位置之後，同樣壓力下，CPU 佔用不再那麼高，並且整體吞吐量有了明顯的提升。

微信搜尋“乾貨滿滿張雜湊”關注公眾號，每日一刷，輕鬆提升技術，斬獲各種offer：

我會經常發一些很好的各種框架的官方社群的新聞視訊資料並加上個人翻譯字幕到如下地址（也包括上面的公眾號），歡迎關注：

相關文章