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

往期回顧：

??為什么我建議在復雜但是性能關鍵的表上所有查詢都加上 force index??。

在業務一開始上線的時候，我們線上日志級別是 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這個事件查看：

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

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

這些線程是 reactor-netty 處理業務的線程，觀察其他實例，發現正常情況下，并不會有這么高的 CPU 負載。那么為啥會有這么高的負載呢?通過 Thread Dump 來看一下線程堆棧有何發現.

通過查看多個線程堆棧 dump，發現這些線程基本都處于 Runnable，并且執行的方法是原生方法，和StackWalker相關，例如(并且這個與 JFR 中采集的 Method Runnable 事件中占比最高的吻合，可以基本確認這個線程的 CPU 主要消耗在這個堆棧當前對應的方法上)：

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

• 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 之前，獲取當前線程(我們這里沒有要獲取其他線程的堆棧的情況，都是當前線程)的堆棧可以通過：

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

Java 9 之后，添加了新的 StackWalker 接口，結合 Stream 接口來更優雅的讀取堆棧，即：

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

javaClasses.cpp：

然后是 StackWalker，其核心底層源碼是：

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

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

模擬兩種方式獲取調用打印日志方法的代碼位置，與不獲取代碼位置會有多大性能差異。

以下代碼我參考的 Log4j2 官方代碼的單元測試，首先是模擬某一調用深度的堆棧代碼：

然后，編寫測試代碼，對比純執行這個代碼，以及加入獲取堆棧的代碼的性能差異有多大。

執行：查看結果：

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

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

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

測試結果：

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

結論與建議

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

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

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

我們在關閉輸出代碼行位置之后，同樣壓力下，CPU 占用不再那么高，并且整體吞吐量有了明顯的提升。