SpringForAll - 必須拿捏：測試和性能監控神器 JMH & Arthas－鑽石舞台

Nov 07 Mon 2022 06:30
SpringForAll - 必須拿捏：測試和性能監控神器 JMH & Arthas

關注我

，回復關鍵字「spring」，

免費領取Spring學習資料。

最近的工作日並不算太平，各種大大小小的case和解case，發現已經有好久好久沒有靜下心來專心寫點東西了。不過倒還是堅持利用業餘時間學習了不少微課上的東西，發現大佬們總結的東西還是不一樣，相比於大學時的那些枯燥的課本，大佬們總結出來的內容更活，更加容易理解。自己後面也會把大佬們的東西好好消化吸收，變成自己的東西用文字性的東西表達出來。

今天想總結的東西是最近工作中使用到的測試工具JMH以及Java運行時監控工具Arthas。他們在我的實際工作中也算是幫了大忙。所以在這裡拋磚引玉一下這些工具的使用方法。同時也加深一下自己對這些工具的熟悉程度。

對這兩個工具，我都會首先簡單介紹一下這些工具的大致使用場景，然後會使用一個在工作中真正遇到的性能問題排查為例詳細講解這兩個工具的實際用法。話不多說，直奔主題。

問題描述

為了能夠讓我後面的實例能夠貫穿這兩個工具的使用，我首先簡單描述下我們在開發中遇到的實際的性能問題。然後再引出這兩個性能工具的實際使用，看我們如何使用這兩個工具成功定位到性能瓶頸的。

問題如下：為了能夠支持丟失率，我們將原先log4j2 的Async+自定義Appender的方式進行了修正，把異步的邏輯放到了自己改版後的Appender中。但我們發現修改後日誌性能要比之前Async+自定義Appender的方式下降不少。這裡由於隱私原因我並沒有用實際公司中的實例，這裡我用了一種其他同樣能夠體現問題的方式。我們暫時先不給出具體的配置文件，先給出性能測試代碼和結果

packagecom.bryantchang.appendertest;importorg.slf4j.Logger;importorg.slf4j.LoggerFactory;publicclassAppenderTest{privatestaticfinalStringLOGGER_NAME_DEFAULT="defaultLogger";privatestaticfinalStringLOGGER_NAME_INCLUDE="includeLocationLogger";privatestaticfinalLoggerLOGGER=LoggerFactory.getLogger(LOGGER_NAME_INCLUDE);publicstaticfinallongBATCH=10000;publicstaticvoidmain(String[]args)throwsInterruptedException{while(true){longstart,end;start=System.currentTimeMillis();for(inti=0;i<BATCH;i++){LOGGER.info("msgis{}",i);}end=System.currentTimeMillis();System.out.println("durationof"+LOGGER_NAME_INCLUDE+"is"+(end-start)+"ms");Thread.sleep(1000);}}}

代碼邏輯及其簡單，就是調用logger.info每次打印10000條日誌，然後記錄耗時。兩者的對比如下

對比結果

從這兩張圖片中我們能夠看到同樣的邏輯，兩個程序的耗時差距相差了數十倍，但看圖片，貌似僅僅是logger的名稱不一樣。對上面的實驗結果進行分析，我們可能會有兩個疑問

上面的代碼測試是否標準，規範

如果真的是性能問題，那麼這兩個代碼到底在哪個方法上有了這麼大的差距導致了最終的性能差異

下面這兩個工具就分別來回答這兩個問題

JMH簡介

第一個問題就是，測試的方法是否標準。我們在編寫代碼時用的是死循環+前後「掐秒表」的方式。假如我們要再加個多線程的測試，我們還需要搞一個線程池，除了代碼本身的邏輯還要關心測試的邏輯。

我們會想，有沒有一款工具能夠將我們從測試邏輯中徹底解放出來，只需要關心我們需要測試的代碼邏輯。JMH就是這樣一款Java的測試框架。下面是JMH的官方定義

JMH 是一個面向 Java 語言或者其他 Java 虛擬機語言的性能基準測試框架

這裡面我們需要注意的是，JMH所測試的方法約簡單越好，依賴越少越好，最適合的場景就是，測試兩個集合put，get性能，例如ArrayList與LinkedList的對比等，這裡我們需要測試的是批量打一批日誌所需要的時間，也基本符合使用JMH的測試場景。下面是測試代碼，bench框架代碼以及主函數。

待測試方法

publicclassLogBenchMarkWorker{privateLogBenchMarkWorker(){}privatestaticclassLogBenchMarkWorkerInstance{privatestaticfinalLogBenchMarkWorkerinstance=newLogBenchMarkWorker();}publicstaticLogBenchMarkWorkergetInstance(){returnLogBenchMarkWorkerInstance.instance;}privatestaticfinalStringLOGGER_DEFAULT_NAME="defaultLogger";privatestaticfinalStringLOGGER_INCLUDE_LOCATION="includeLocationLogger";privatestaticfinalLoggerLOGGER=LoggerFactory.getLogger(LOGGER_DEFAULT_NAME);privatestaticlongBATCH_SIZE=10000;publicvoidlogBatch(){for(inti=0;i<BATCH_SIZE;i++){LOGGER.info("msgis{}",i);}}}

可以看到待測試方法非常簡單，就是單批次一次性打印10000條日誌的操作，所以並沒有需要額外說明的部分。下面我們再來看benchmark部分。

publicclassLogBenchMarkMain{@Benchmark@BenchmarkMode(Mode.AverageTime)@Fork(value=1)@Threads(1)publicvoidtestLog1(){LogBenchMarkWorker.getInstance().logBatch();}@Benchmark@BenchmarkMode(Mode.AverageTime)@Fork(value=1)@Threads(4)publicvoidtestLog4(){LogBenchMarkWorker.getInstance().logBatch();}@Benchmark@BenchmarkMode(Mode.AverageTime)@Fork(value=1)@Threads(8)publicvoidtestLog8(){LogBenchMarkWorker.getInstance().logBatch();}@Benchmark@BenchmarkMode(Mode.AverageTime)@Fork(value=1)@Threads(16)publicvoidtestLog16(){LogBenchMarkWorker.getInstance().logBatch();}

在這段代碼中，我們就會發現有了一些JMH中特有的東西，我下面進行簡要介紹。

Benchmark註解：標識在某個具體方法上，表示這個方法將是一個被測試的最小方法，在JMH中成為一個OPS

BenmarkMode:測試類型，JMH提供了幾種不同的Mode

Throughput:整體吞吐量

AverageTime:調用的平均時間，每次OPS執行的時間

SampleTime:取樣，給出不同比例的ops時間，例如99%的ops時間，99.99%的ops時間

fork：fork的次數，如果設置為2，JMH會fork出兩個進程來測試

Threads：很容易理解，這個參數表示這個方法同時被多少個線程執行

在上面的代碼中，我定義了4個待測試的方法，方法的Fork，BenchmarkMode均為測試單次OPS的平均時間，但4個方法的線程數不同。

除了這幾個參數，還有幾個參數，我會在main函數裡面來講，main代碼如下所示

publicclassMain{publicstaticvoidmain(String[]args)throwsRunnerException{Optionsoptions=newOptionsBuilder().include(LogBenchMarkMain.class.getSimpleName()).warmupIterations(5).measurementIterations(5).output("logs/BenchmarkCommon.log").build();newRunner(options).run();}}

我們可以看到，在main函數中，我們就是要設置JMH的基礎配置，這裡面的幾個配置參數含義如下：

include:benchmark所在類的名字，可以使用正則表達

warmupIteration:預熱的迭代次數，這裡為什麼要預熱的原因是由於JIT的存在，隨着代碼的運行，會動態對代碼的運行進行優化。因此在測試過程中需要先預熱幾輪，讓代碼運行穩定後再實際進行測試

measurementIterations:實際測試輪次

output:測試報告輸出位置

我分別用兩種logger運行一下測試，查看性能測試報告對比

使用普通logger

LogBenchMarkMain.testLog1avgt50.006±0.001s/opLogBenchMarkMain.testLog16avgt50.062±0.026s/opLogBenchMarkMain.testLog4avgt50.006±0.002s/opLogBenchMarkMain.testLog8avgt50.040±0.004s/op

使用了INCLUDE_LOCATION的logger

LogBenchMarkMain.testLog1avgt50.379±0.007s/opLogBenchMarkMain.testLog16avgt51.784±0.670s/opLogBenchMarkMain.testLog4avgt50.378±0.003s/opLogBenchMarkMain.testLog8avgt50.776±0.070s/op

這裡我們看到，性能差距立現。使用INCLUDE_LOCATION的性能要明顯低於使用普通logger的性能。這是我們一定很好奇，並且問一句「到底慢在哪」！！

Arthas 我的代碼在運行時到底做了什麼

Arthas是阿里開源的一款java調試神器，與greys類似，不過有着比greys更加強大的功能，例如，可以直接繪製java方法調用的火焰圖等。

這兩個工具的原理都是使用了Java強大的字節碼技術。畢竟我也不是JVM大佬，所以具體的實現細節沒法展開，我們要做的就是站在巨人的肩膀上，接受並用熟練的使用好這些好用的性能監控工具。

實際操作

talk is cheap, show me your code,既然是工具，我們直接進行實際操作。我們在本機運行我們一開始的程序，然後講解arthas的使用方法。

我們首先通過jps找到程序的進程號，然後直接通過arthas給到的as.sh對我們運行的程序進行字節碼增強，然後啟動arthas，命令如下

./as.shpid

這個就是arthas的啟動界面了，我們使用help命令查看工具所支持的功能

可以看到，arthas支持查看當前jvm的狀態，查看當前的線程狀態，監控某些方法的調用時間，trace，profile生成火焰圖等，功能一應俱全

我們這裡也只將幾個比較常用的命令，其他的命令如果大家感興趣可以詳見官網arthas官網。這篇文章主要介紹下面幾個功能

反編譯代碼

監控某個方法的調用

查看某個方法的調用和返回值

trace某個方法

監控方法調用

這個主要的命令為monitor，根據官網的介紹，常用的使用方法為

monitor-cdurationclassNamemethodName

其中duration代表每隔幾秒展示一次統計結果，即單次的統計周期，className就是類的全限定名，methodname就是方法的名字，這裡面我們查看的方法是Logger類的info方法，我們分別對使用兩種不同logger的info方法。

這裡面的類是org.slf4j.Logger，方法時info，我們的監控語句為

monitor-c5org.slf4j.Loggerinfo

監控結果如下

使用普通appender

使用include appender

我們可以看到，使用include appeder的打印日誌方法要比普通的appender高出了3倍，這就不禁讓我們有了疑問，究竟這兩個方法各個步驟耗時如何呢。下面我們就介紹第二條命令，trace方法。

trace命令 & jad命令

這兩個程序的log4j2配置文件如下

<?xmlversion="1.0"encoding="UTF-8"?><configurationstatus="warn"monitorInterval="30"><appenders><Consolename="console"target="SYSTEM_OUT"><ThresholdFilterlevel="warn"onMatch="ACCEPT"onMismatch="DENY"/><PatternLayoutpattern="[%d{HH:mm:ss.SSS}][%-5p]%l-%m%n"/></Console><Asyncname="AsyncDefault"blocking="false"includeLocation="false"><AppenderRefref="fileAppender"/></Async><Asyncname="AsyncIncludeLocation"blocking="false"includeLocation="true"><AppenderRefref="fileAppender"/></Async><Filename="fileAppender"fileName="log/test.log"append="false"><PatternLayoutpattern="[%d{HH:mm:ss.SSS}][%-5p]%l-%m%n"/></File><Filename="ERROR"fileName="logs/error.log"><ThresholdFilterlevel="error"onMatch="ACCEPT"onMismatch="DENY"/><PatternLayoutpattern="[%d{yyyy.MM.dd'at'HH:mm:ssz}][%-5p]%l-%m%n"/></File><RollingFilename="rollingFile"fileName="logs/app.log"filePattern="logs/$${date:yyyy-MM}/web-%d{yyyy-MM-dd}.log.gz"><PatternLayoutpattern="[%d{yyyy-MM-ddHH:mm:ss}][%-5p]%l-%m%n"/><Policies><TimeBasedTriggeringPolicymodulate="true"interval="1"/></Policies><DefaultRolloverStrategy><DeletebasePath="logs"maxDepth="2"><IfFileNameglob="*/*.log.gz"/><IfLastModifiedage="7d"/></Delete></DefaultRolloverStrategy></RollingFile></appenders><loggers><loggername="defaultLogger"additivity="false"><appender-refref="AsyncDefault"></appender-ref></logger><loggername="includeLocationLogger"additivity="false"><appender-refref="AsyncIncludeLocation"></appender-ref></logger><rootlevel="INFO"></root></loggers></configuration>

我們都是用了一個AsyncAppender套用了一個FileAppender。查看fileAppender，發現二者相同完全沒區別，只有asyncAppender中的一個選項有區別，這就是includeLocation，一個是false，另一個是true。至於這個參數的含義，我們暫時不討論，我們現在知道問題可能出在AsyncAppender裡面，但是我們該如何驗證呢。trace命令就有了大用場。

trace命令的基本用法與monitor類似，其中主要的一個參數是-n則是代表trace多少次的意思

trace-ntrace_timesclassNamemethodName

我在之前Log4j2的相關博客裡面講到過，任何一個appender，最核心的方法就是他的append方法。所以我們分別trace兩個程序的append方法。

trace-n5org.apache.logging.log4j.core.appender.AsyncAppenderappend

trace結果如下

使用普通appender

使用include appender

我們立刻可以發現，兩個trace的熱點方法不一樣，在使用include的appender中，耗時最長的方法時org.apache.logging.log4j.core.impl.Log4jLogEvent類中的createMemento方法，那麼怎麼才能知道這個方法到底做了啥呢，那就請出我們下一個常用命令jad，這個命令能夠反編譯出對應方法的代碼。這裡我們jad一下上面說的那個createMemento方法，命令很簡單

jadorg.apache.logging.log4j.core.impl.Log4jLogEventcreateMemento

結果如下

我們發現，這個方法中有個includeLocation參數，這個和我們的看到的兩個appender的唯一不同的配置相吻合，我們此時應該有這個猜想，會不會就是這個參數導致的呢？為了驗證這個猜想，我們引出下一個命令,watch

watch命令

watch命令能夠觀察到某個特定方法的入參，返回值等信息，我們使用這個命令查看一下這個createMemento方法的入參，如果兩個程序的入參不同，那基本可以斷定是這個原因引起命令如下

watchorg.apache.logging.log4j.core.impl.Log4jLogEventcreateMemento"params"-x2-n5-b-f

這裡面的參數含義如下

-x參數展開層次

-n執行次數

-b查看方法調用前狀態

-f方法調用後

其中的param代表查看方法的調用參數列表，還有其他的監控項詳見官網官網

最終watch結果如下

使用普通logger

使用include

果不其然，這兩個參數果然是一個true一個false，我們簡單看下這個參數是如何傳進來的，我們jad一下AsyncAppender的append方法

我們發現這個includeLocation正是appender的一個屬性，也就是我們xml中配置的那個屬性。查看官網的相關分析，我們看到這個參數會使log的性能下降5–10倍

不過為了一探究竟，我還是靜態跟了一下這段代碼

這個includeLocation會在event的createMemento中被用到，在序列化生成對象時會創建一個LogEventProxy，代碼如下

publicLogEventProxy(finalLogEventevent,finalbooleanincludeLocation){this.loggerFQCN=event.getLoggerFqcn();this.marker=event.getMarker();this.level=event.getLevel();this.loggerName=event.getLoggerName();finalMessagemsg=event.getMessage();this.message=msginstanceofReusableMessage?memento((ReusableMessage)msg):msg;this.timeMillis=event.getTimeMillis();this.thrown=event.getThrown();this.thrownProxy=event.getThrownProxy();this.contextData=memento(event.getContextData());this.contextStack=event.getContextStack();this.source=includeLocation?event.getSource():null;this.threadId=event.getThreadId();this.threadName=event.getThreadName();this.threadPriority=event.getThreadPriority();this.isLocationRequired=includeLocation;this.isEndOfBatch=event.isEndOfBatch();this.nanoTime=event.getNanoTime();}

如果includeLocation為true，那麼就會調用getSource函數，跟進去查看，代碼如下

publicStackTraceElementgetSource(){if(source!=null){returnsource;}if(loggerFqcn==null||!includeLocation){returnnull;}source=Log4jLogEvent.calcLocation(loggerFqcn);returnsource;}publicstaticStackTraceElementcalcLocation(finalStringfqcnOfLogger){if(fqcnOfLogger==null){returnnull;}//LOG4J2-1029newThrowable().getStackTraceisfasterthanThread.currentThread().getStackTrace().finalStackTraceElement[]stackTrace=newThrowable().getStackTrace();StackTraceElementlast=null;for(inti=stackTrace.length-1;i>0;i--){finalStringclassName=stackTrace[i].getClassName();if(fqcnOfLogger.equals(className)){returnlast;}last=stackTrace[i];}returnnull;}

我們看到他會從整個的調用棧中去尋找調用這個方法的代碼行，其性能可想而知。我們用arthas監控一下，驗證一下。

首先我們trace crateMemento方法

trace-n5org.apache.logging.log4j.core.impl.Log4jLogEventcreateMemento