建站
咨詢
售后
建站咨詢
新聞中心
本文是“為什么我建議”系列第二篇，本系列中會針對一些在高并發(fā)場景下，我對于組內后臺開發(fā)的一些開發(fā)建議以及開發(fā)規(guī)范的要求進行說明和分析解讀，相信能讓各位在面對高并發(fā)業(yè)務的時候避開一些坑。
我們提供的服務有：網(wǎng)站制作、做網(wǎng)站、微信公眾號開發(fā)、網(wǎng)站優(yōu)化、網(wǎng)站認證、新林ssl等。為上千多家企事業(yè)單位解決了網(wǎng)站和推廣的問題。提供周到的售前咨詢和貼心的售后服務，是有科學管理、有技術的新林網(wǎng)站制作公司
往期回顧：
??為什么我建議在復雜但是性能關鍵的表上所有查詢都加上 force index??。
在業(yè)務一開始上線的時候，我們線上日志級別是 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。隨著業(yè)務的增長，我們發(fā)現(xiàn)經(jīng)常有的實例 CPU 占用非常之高(尤其是那種短時間內有大量日志輸出的)，我們 dump 了 JFR 進行進一步定位：
首先我們來看 GC，我們的 GC 算法是 G1，主要通過 G1 Garbage Collection這個事件查看：
發(fā)現(xiàn) GC 全部為 Young GC，且耗時比較正常，頻率上也沒有什么明顯異常。
接下來來看，CPU 占用相關。直接看 Thread CPU Load 這個事件，看每個線程的 CPU 占用情況。發(fā)現(xiàn)reactor-http-epoll線程池的線程，CPU 占用很高，加在一起，接近了 100%。
這些線程是 reactor-netty 處理業(yè)務的線程，觀察其他實例，發(fā)現(xiàn)正常情況下，并不會有這么高的 CPU 負載。那么為啥會有這么高的負載呢?通過 Thread Dump 來看一下線程堆棧有何發(fā)現(xiàn).
通過查看多個線程堆棧 dump，發(fā)現(xiàn)這些線程基本都處于 Runnable，并且執(zhí)行的方法是原生方法，和StackWalker相關，例如(并且這個與 JFR 中采集的 Method Runnable 事件中占比最高的吻合，可以基本確認這個線程的 CPU 主要消耗在這個堆棧當前對應的方法上)：
主要和這兩個原生方法有關：
- java.lang.StackStreamFactory$AbstractStackWalker.callStackWalk。
- java.lang.StackStreamFactory$AbstractStackWalker.fetchStackFrames。
并且需要注意微服務中線程堆棧會很深(150左右)，對于響應式代碼更是如此(可能會到300)，主要是因為 servlet 與 filter 的設計是責任鏈模式，各個 filter 會不斷加入堆棧。響應式的代碼就更是這樣了，一層套一層，各種拼接觀察點。上面列出的堆棧就是響應式的堆棧。
會到那兩個原生方法，其實這里的代碼是在做一件事，就是日志中要輸出調用打印日志方法的代碼位置，包括類名，方法名，方法行數(shù)這些。在上面我給出的線程堆棧的例子中，調用打印日志方法的代碼位置信息就是這一行：at。
com.xxx.apigateway.filter.AccessCheckFilter.filter(AccessCheckFilter.java:144)，這一行中，我們使用 log.info() 輸出了一些日志。
可以看出，Log4j2 是通過獲取當前線程堆棧來獲取調用打印日志方法的代碼位置的。并且并不是堆棧中的棧頂就是調用打印日志方法的代碼位置，而是找到 log4j2 堆棧元素之后的第一個堆棧元素才是打印日志方法的代碼位置
Log4j2 中是如何獲取堆棧的
我們先來自己思考下如何實現(xiàn)：首先 Java 9 之前，獲取當前線程(我們這里沒有要獲取其他線程的堆棧的情況，都是當前線程)的堆棧可以通過：
其中 Thread.currentThread().getStackTrace(); 的底層其實就是 new Exception().getStackTrace(); 所以其實本質是一樣的。
Java 9 之后，添加了新的 StackWalker 接口，結合 Stream 接口來更優(yōu)雅的讀取堆棧，即：
我們先來看看 new Exception().getStackTrace(); 底層是如何獲取堆棧的：
javaClasses.cpp：
然后是 StackWalker，其核心底層源碼是：
可以看出，核心都是填充堆棧詳細信息，區(qū)別是一個直接填充所有的，一個會減少填充堆棧信息。填充堆棧信息，主要訪問的其實就是 SymbolTable，StringTable 這些，因為我們要看到的是具體的類名方法名，而不是類的地址以及方法的地址，更不是類名的地址以及方法名的地址。那么很明顯：通過 Exception 獲取堆棧對于 Symbol Table 以及 String Table 的訪問次數(shù)要比 StackWalker 的多，因為要填充的堆棧多。
我們接下來測試下，模擬在不同堆棧深度下，獲取代碼執(zhí)行會給原本的代碼帶來多少性能衰減。
模擬兩種方式獲取調用打印日志方法的代碼位置，與不獲取代碼位置會有多大性能差異。
以下代碼我參考的 Log4j2 官方代碼的單元測試，首先是模擬某一調用深度的堆棧代碼：
然后，編寫測試代碼，對比純執(zhí)行這個代碼，以及加入獲取堆棧的代碼的性能差異有多大。
執(zhí)行：查看結果：
從結果可以看出，獲取代碼執(zhí)行位置，也就是獲取堆棧，會造成比較大的性能損失。同時，這個性能損失，和堆棧填充相關。填充的堆棧越多，損失越大?？梢詮?StackWalker 的性能優(yōu)于通過異常獲取堆棧，并且隨著堆棧深度增加差距越來越明顯看出來。
為何會慢?String::intern 帶來的性能衰減程度測試
這個性能衰減，從前面的對于底層 JVM 源碼的分析，其實可以看出來是因為對于 StringTable 以及 SymbolTable 的訪問，我們來模擬下這個訪問，其實底層對于 StringTable 的訪問都是通過 String 的 intern 方法，即我們可以通過 String::intern 方法進行模擬測試，測試代碼如下：
測試結果：
對比StackWalkBenchmark.baseline 與 StackWalkBenchmark.toString 的結果，我們看出 bh.consume(time); 本身沒有什么性能損失。但是通過將他們與 StackWalkBenchmark.intern 以及 StackWalkBenchmark.intern3 的結果對比，發(fā)現(xiàn)這個性能衰減，也是很嚴重的，并且訪問的越多，性能衰減越嚴重(類比前面獲取堆棧)。
結論與建議
由此，我們可以得出如下直觀的結論：
- 日志中輸出代碼行位置，Java 9 之前通過異常獲取堆棧，Java 9 之后通過 StackWalker。
- 兩種方式都需要訪問 SymbolTable 以及 StringTable，StackWalker 可以通過減少要填充的堆棧來減少訪問量。
- 兩種方式對于性能的衰減都是很嚴重的。
由此，我建議：對于微服務環(huán)境，尤其是響應式微服務環(huán)境，堆棧深度非常深，如果會輸出大量的日志的話，這個日志是不能帶有代碼位置的，否則會造成嚴重的性能衰減。
我們在關閉輸出代碼行位置之后，同樣壓力下，CPU 占用不再那么高，并且整體吞吐量有了明顯的提升。
分享名稱：為什么我建議線上高并發(fā)量的日志輸出的時候不能帶有代碼位置
本文URL：http://m.5511xx.com/article/cdoghgj.html
