本文是“為什么我建議”系列第二篇，本系列中會(huì)針對(duì)一些在高并發(fā)場景下，我對(duì)于組內(nèi)后臺(tái)開發(fā)的一些開發(fā)建議以及開發(fā)規(guī)范的要求進(jìn)行說明和分析解讀，相信能讓各位在面對(duì)高并發(fā)業(yè)務(wù)的時(shí)候避開一些坑。

往期回顧：

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

在業(yè)務(wù)一開始上線的時(shí)候，我們線上日志級(jí)別是 INFO，并且在日志內(nèi)容中輸出了代碼位置，格式例如：

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。隨著業(yè)務(wù)的增長，我們發(fā)現(xiàn)經(jīng)常有的實(shí)例 CPU 占用非常之高(尤其是那種短時(shí)間內(nèi)有大量日志輸出的)，我們 dump 了 JFR 進(jìn)行進(jìn)一步定位：

首先我們來看 GC，我們的 GC 算法是 G1，主要通過 G1 Garbage Collection這個(gè)事件查看：

發(fā)現(xiàn) GC 全部為 Young GC，且耗時(shí)比較正常，頻率上也沒有什么明顯異常。

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

這些線程是 reactor-netty 處理業(yè)務(wù)的線程，觀察其他實(shí)例，發(fā)現(xiàn)正常情況下，并不會(huì)有這么高的 CPU 負(fù)載。那么為啥會(huì)有這么高的負(fù)載呢?通過 Thread Dump 來看一下線程堆棧有何發(fā)現(xiàn).

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

主要和這兩個(gè)原生方法有關(guān)：

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

并且需要注意微服務(wù)中線程堆棧會(huì)很深(150左右)，對(duì)于響應(yīng)式代碼更是如此(可能會(huì)到300)，主要是因?yàn)?servlet 與 filter 的設(shè)計(jì)是責(zé)任鏈模式，各個(gè) filter 會(huì)不斷加入堆棧。響應(yīng)式的代碼就更是這樣了，一層套一層，各種拼接觀察點(diǎn)。上面列出的堆棧就是響應(yīng)式的堆棧。

會(huì)到那兩個(gè)原生方法，其實(shí)這里的代碼是在做一件事，就是日志中要輸出調(diào)用打印日志方法的代碼位置，包括類名，方法名，方法行數(shù)這些。在上面我給出的線程堆棧的例子中，調(diào)用打印日志方法的代碼位置信息就是這一行：at。

com.xxx.apigateway.filter.AccessCheckFilter.filter(AccessCheckFilter.java:144)，這一行中，我們使用 log.info() 輸出了一些日志。

可以看出，Log4j2 是通過獲取當(dāng)前線程堆棧來獲取調(diào)用打印日志方法的代碼位置的。并且并不是堆棧中的棧頂就是調(diào)用打印日志方法的代碼位置，而是找到 log4j2 堆棧元素之后的第一個(gè)堆棧元素才是打印日志方法的代碼位置

Log4j2 中是如何獲取堆棧的

我們先來自己思考下如何實(shí)現(xiàn)：首先 Java 9 之前，獲取當(dāng)前線程(我們這里沒有要獲取其他線程的堆棧的情況，都是當(dāng)前線程)的堆棧可以通過：

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

Java 9 之后，添加了新的 StackWalker 接口，結(jié)合 Stream 接口來更優(yōu)雅的讀取堆棧，即：

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

javaClasses.cpp：

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

可以看出，核心都是填充堆棧詳細(xì)信息，區(qū)別是一個(gè)直接填充所有的，一個(gè)會(huì)減少填充堆棧信息。填充堆棧信息，主要訪問的其實(shí)就是 SymbolTable，StringTable 這些，因?yàn)槲覀円吹降氖蔷唧w的類名方法名，而不是類的地址以及方法的地址，更不是類名的地址以及方法名的地址。那么很明顯：通過 Exception 獲取堆棧對(duì)于 Symbol Table 以及 String Table 的訪問次數(shù)要比 StackWalker 的多，因?yàn)橐畛涞亩褩６唷?/p>

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

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

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

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

執(zhí)行：查看結(jié)果：

從結(jié)果可以看出，獲取代碼執(zhí)行位置，也就是獲取堆棧，會(huì)造成比較大的性能損失。同時(shí)，這個(gè)性能損失，和堆棧填充相關(guān)。填充的堆棧越多，損失越大?？梢詮? StackWalker 的性能優(yōu)于通過異常獲取堆棧，并且隨著堆棧深度增加差距越來越明顯看出來。

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

這個(gè)性能衰減，從前面的對(duì)于底層 JVM 源碼的分析，其實(shí)可以看出來是因?yàn)閷?duì)于 StringTable 以及 SymbolTable 的訪問，我們來模擬下這個(gè)訪問，其實(shí)底層對(duì)于 StringTable 的訪問都是通過 String 的 intern 方法，即我們可以通過 String::intern 方法進(jìn)行模擬測試，測試代碼如下：

測試結(jié)果：

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

結(jié)論與建議

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

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

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

我們?cè)陉P(guān)閉輸出代碼行位置之后，同樣壓力下，CPU 占用不再那么高，并且整體吞吐量有了明顯的提升。