電子發(fā)燒友App
Arthas 簡(jiǎn)介
Arthas 快速開始
使用 Trace 命令統(tǒng)計(jì)方法耗時(shí)
不知道大家有沒有遇到這種情況，接口業(yè)務(wù)邏輯寫完后，用 postman 一調(diào)，發(fā)現(xiàn)接口響應(yīng)時(shí)間好長(zhǎng)，不得不對(duì)接口進(jìn)行優(yōu)化。但是此時(shí)接口的代碼往往邏輯比較復(fù)雜，調(diào)用層次也比較多，很難定位到耗時(shí)較長(zhǎng)的代碼塊
遇到這種情況大家都是如何定位耗時(shí)代碼塊的呢？
我看到很多人都是直接用System.currentTimeMillis()對(duì)代碼進(jìn)行埋點(diǎn)
public?static?void?main(String[]?args)?{??
????Long?startTime?=?System.currentTimeMillis();??
????exec();??
????Long?endTime?=?System.currentTimeMillis();??
????log.info("exec?方法執(zhí)行耗時(shí):{}ms",?endTime?-?startTime);??
}??
或者用StopWatch打印方法耗時(shí)
public?static?void?main(String[]?args)?throws?InterruptedException?{??
????StopWatch?stopWatch?=?new?StopWatch();??
????stopWatch.start("exec");??
????exec();??
????stopWatch.stop();??
????System.out.println(stopWatch.prettyPrint());??
}??
這兩種方法本質(zhì)上是一樣的，都是通過手動(dòng)在代碼塊上進(jìn)行埋點(diǎn)，打印出方法的耗時(shí)，該方法不僅費(fèi)時(shí)費(fèi)力，而且對(duì)代碼有侵入，修復(fù)問題后刪掉代碼還是一個(gè)麻煩事
下面介紹如果通過Arthas定位耗時(shí)代碼塊
Arthas 簡(jiǎn)介
Arthas是阿里開源的一款 Java 診斷工具，可以在無需重啟 JVM 的情況下，實(shí)時(shí)查看應(yīng)用 load、內(nèi)存、gc、線程等狀態(tài)信息，還能實(shí)時(shí)查看方法調(diào)用入?yún)ⅰ⒊鰠?、方法調(diào)用耗時(shí)等
Arthas 快速開始
直接下載Arthasjar 包，然后用java -jar命令啟動(dòng)即可
$?curl?-O?https://arthas.aliyun.com/arthas-boot.jar?? $?java?-jar?arthas-boot.jar??
Arthas啟動(dòng)的時(shí)候，會(huì)打印出當(dāng)前運(yùn)行的 java 進(jìn)程
$?java?-jar?arthas-boot.jar?? [INFO]?JAVA_HOME:?/Library/Java/JavaVirtualMachines/jdk1.8.0_351.jdk/Contents/Home/jre?? [INFO]?arthas-boot?version:?3.6.9?? [INFO]?Found?existing?java?process,?please?choose?one?and?input?the?serial?number?of?the?process,?eg?:?1.?Then?hit?ENTER.?? *?[1]:?12512?com.huangxy.springstudy.SpringStudyApplication?? ??[2]:?12511?org.jetbrains.jps.cmdline.Launcher??
然后可以選擇我們需要 attach 的 java 進(jìn)程，這里我們選擇 1，然后按回車。Arthas 會(huì) attach 到目標(biāo)進(jìn)程上，并輸出日志：
[INFO]?arthas?home:?/Users/huangxiaoyu/.arthas/lib/3.6.9/arthas?? [INFO]?Try?to?attach?process?12512?? [INFO]?Attach?process?12512?success.?? [INFO]?arthas-client?connect?127.0.0.1?3658?? ??,---.??,------.?,--------.,--.??,--.??,---.???,---.?? ?/??O???|??.--.?''--.??.--'|??'--'??|?/??O???'???.-'?? |??.-.??||??'--'.'???|??|???|??.--.??||??.-.??|`.??`-.?? |??|?|??||??|??????|??|???|??|??|??||??|?|??|.-'????|?? `--'?`--'`--'?'--'???`--'???`--'??`--'`--'?`--'`-----'?? ?? wiki???????https://arthas.aliyun.com/doc?? tutorials??https://arthas.aliyun.com/doc/arthas-tutorials.html?? version????3.6.9?? main_class?com.huangxy.springstudy.SpringStudyApplication?? pid????????12512?? time???????2023-07-25?09:14:22??
到這里，Arthas 已經(jīng) attach 到我們的目標(biāo)進(jìn)程上了，我們嘗試使用dashboad命令，查看進(jìn)程的信息
$?dashboard?? ID???NAME???????????????????????????GROUP??????????PRIORITY??STATE?????%CPU??????DELTA_TIME?TIME??????INTERRUPT?DAEMON?? 36???DestroyJavaVM??????????????????main???????????5?????????RUNNABLE??0.0???????0.000??????0:1.748???false?????false?? -1???C1?CompilerThread3?????????????-??????????????-1????????-?????????0.0???????0.000??????0:0.761???false?????true?? -1???VM?Periodic?Task?Thread????????-??????????????-1????????-?????????0.0???????0.000??????0:0.237???false?????true?? 24???http-nio-8081-exec-1???????????main???????????5?????????WAITING???0.0???????0.000??????0:0.098???false?????true?? -1???VM?Thread??????????????????????-??????????????-1????????-?????????0.0???????0.000??????0:0.071???false?????true?? 25???http-nio-8081-exec-2???????????main???????????5?????????WAITING???0.0???????0.000??????0:0.055???false?????true?? 54???arthas-NettyHttpTelnetBootstra?system?????????5?????????RUNNABLE??0.0???????0.000??????0:0.054???false?????true?? -1???GC?task?thread#8?(ParallelGC)??-??????????????-1????????-?????????0.0???????0.000??????0:0.043???false?????true?? -1???GC?task?thread#1?(ParallelGC)??-??????????????-1????????-?????????0.0???????0.000??????0:0.043???false?????true?? -1???GC?task?thread#7?(ParallelGC)??-??????????????-1????????-?????????0.0???????0.000??????0:0.042???false?????true?? -1???GC?task?thread#6?(ParallelGC)??-??????????????-1????????-?????????0.0???????0.000??????0:0.042???false?????true?? -1???GC?task?thread#0?(ParallelGC)??-??????????????-1????????-?????????0.0???????0.000??????0:0.042???false?????true?? -1???GC?task?thread#9?(ParallelGC)??-??????????????-1????????-?????????0.0???????0.000??????0:0.042???false?????true?? -1???GC?task?thread#2?(ParallelGC)??-??????????????-1????????-?????????0.0???????0.000??????0:0.042???false?????true?? -1???GC?task?thread#3?(ParallelGC)??-??????????????-1????????-?????????0.0???????0.000??????0:0.042???false?????true?? -1???GC?task?thread#5?(ParallelGC)??-??????????????-1????????-?????????0.0???????0.000??????0:0.042???false?????true?? -1???GC?task?thread#4?(ParallelGC)??-??????????????-1????????-?????????0.0???????0.000??????0:0.042???false?????true?? Memory????????????????????used?????total????max?????usage????GC?? heap??????????????????????83M??????432M?????7282M???1.14%????gc.ps_scavenge.count???????????4?? ps_eden_space?????????????72M??????212M?????2688M???2.69%????gc.ps_scavenge.time(ms)????????24?? ps_survivor_space?????????0K???????21504K???21504K??0.00%????gc.ps_marksweep.count??????????2?? ps_old_gen????????????????10M??????199M?????5461M???0.20%????gc.ps_marksweep.time(ms)???????61?? nonheap???????????????????53M??????56M??????-1??????94.71%?? code_cache????????????????6M???????7M???????240M????2.87%?? metaspace?????????????????40M??????43M??????-1??????94.45%?? compressed_class_space????5M???????5M???????1024M???0.53%?? direct????????????????????16K??????16K??????-???????100.01%?? mapped????????????????????0K???????0K???????-???????0.00%?? Runtime?? os.name??????????????????????????????????????????????????????Mac?OS?X?? os.version???????????????????????????????????????????????????13.0.1?? java.version?????????????????????????????????????????????????1.8.0_351?? java.home????????????????????????????????????????????????????/Library/Java/JavaVirtualMachines/jdk1.8.0_351.jdk/Contents/?? ?????????????????????????????????????????????????????????????Home/jre?? systemload.average???????????????????????????????????????????3.80?? processors???????????????????????????????????????????????????12??
可以看到dashboad命令會(huì)展示一個(gè)實(shí)時(shí)的數(shù)據(jù)面板，列出了我們平時(shí)比較關(guān)心的數(shù)據(jù)指標(biāo)，如內(nèi)存使用量，gc 狀態(tài)等
更多命令的使用，可以參考官網(wǎng)的命令列表
使用 Trace 命令統(tǒng)計(jì)方法耗時(shí)
trace命令能主動(dòng)搜索class-pattern／method-pattern對(duì)應(yīng)的方法調(diào)用路徑，渲染和統(tǒng)計(jì)整個(gè)調(diào)用鏈路上的所有性能開銷和追蹤調(diào)用鏈路
比如下面接口
@RestController??
public?class?HelloController?{??
??
????@GetMapping("/test")??
????public?String?test()?throws?InterruptedException?{??
???????one();??
???????two();??
???????return?"hello";??
????}??
??
????private?void?two()?throws?InterruptedException?{??
????????Thread.sleep(20);??
????????three();??
????}??
??
????private?void?three()?throws?InterruptedException?{??
????????Thread.sleep(1000);??
????}??
??
????private?void?one()?throws?InterruptedException?{??
????????Thread.sleep(100);??
????}??
??
}??
啟動(dòng)Arthas進(jìn)程，并 attach 到我們的 springboot 項(xiàng)目上，接著使用trace命令跟蹤方法的調(diào)用情況
$?trace?com.huangxy.springstudy.controller.HelloController?test??
trace方法第一個(gè)參數(shù)是要 attach 的類的路徑，第二個(gè)參數(shù)是方法名稱，接著我們調(diào)用一遍接口，就能看到 hello 方法的調(diào)用堆棧及其耗時(shí)
可以看到，這里耗時(shí)比較嚴(yán)重的是tow()方法，花了 1029ms，占了 90.73% 的比重
不過需要注意的是，trace 命令只會(huì) trace 匹配到的函數(shù)里的子調(diào)用，并不會(huì)向下 trace 多層，如果需要 trace 多層，可以用正則匹配多個(gè)函數(shù)，如
$?trace?-E?com.huangxy.springstudy.controller.HelloController?test|two??
?
?
這下更清晰的定位到，導(dǎo)致耗時(shí)過長(zhǎng)的方法是three()方法，定位到方法后，針對(duì)性的優(yōu)化耗時(shí)代碼塊即可
編輯：黃飛
工商網(wǎng)監(jiān)
評(píng)論