接口響應(yīng)慢該如何排查
不知道大家有沒有遇到這種情況，接口業(yè)務(wù)邏輯寫完后，用 postman 一調(diào)，發(fā)現(xiàn)接口響應(yīng)時間好長，不得不對接口進行優(yōu)化。但是此時接口的代碼往往邏輯比較復(fù)雜，調(diào)用層次也比較多，很難定位到耗時較長的代碼塊
遇到這種情況大家都是如何定位耗時代碼塊的呢？
我看到很多人都是直接用System.currentTimeMillis()對代碼進行埋點
public static void main(String[] args) {
Long startTime = System.currentTimeMillis();
exec();
Long endTime = System.currentTimeMillis();
log.info("exec 方法執(zhí)行耗時:{}ms", endTime - startTime);
}
或者用StopWatch打印方法耗時
public static void main(String[] args) throws InterruptedException {
StopWatch stopWatch = new StopWatch();
stopWatch.start("exec");
exec();
stopWatch.stop();
System.out.println(stopWatch.prettyPrint());
}
這兩種方法本質(zhì)上是一樣的，都是通過手動在代碼塊上進行埋點，打印出方法的耗時，該方法不僅費時費力，而且對代碼有侵入，修復(fù)問題后刪掉代碼還是一個麻煩事
下面介紹如果通過Arthas定位耗時代碼塊
Arthas 簡介
Arthas是阿里開源的一款 Java 診斷工具，可以在無需重啟 JVM 的情況下，實時查看應(yīng)用 load、內(nèi)存、gc、線程等狀態(tài)信息，還能實時查看方法調(diào)用入?yún)ⅰ⒊鰠ⅰ⒎椒ㄕ{(diào)用耗時等
Arthas 快速開始
直接下載Arthasjar 包，然后用java -jar命令啟動即可
$ curl -O https://arthas.aliyun.com/arthas-boot.jar
$ java -jar arthas-boot.jar
Arthas啟動的時候，會打印出當(dāng)前運行的 java 進程
$ 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 進程，這里我們選擇 1，然后按回車。Arthas 會 attach 到目標(biāo)進程上，并輸出日志：
[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)進程上了，我們嘗試使用dashboad命令，查看進程的信息
$ 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命令會展示一個實時的數(shù)據(jù)面板，列出了我們平時比較關(guān)心的數(shù)據(jù)指標(biāo)，如內(nèi)存使用量，gc 狀態(tài)等
更多命令的使用，可以參考官網(wǎng)的命令列表
使用 Trace 命令統(tǒng)計方法耗時
trace命令能主動搜索class-pattern／method-pattern對應(yīng)的方法調(diào)用路徑，渲染和統(tǒng)計整個調(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);
}
}
啟動Arthas進程，并 attach 到我們的 springboot 項目上，接著使用trace命令跟蹤方法的調(diào)用情況
$ trace com.huangxy.springstudy.controller.HelloController test
trace方法第一個參數(shù)是要 attach 的類的路徑，第二個參數(shù)是方法名稱，接著我們調(diào)用一遍接口，就能看到 hello 方法的調(diào)用堆棧及其耗時
可以看到，這里耗時比較嚴(yán)重的是tow()方法，花了 1029ms，占了 90.73% 的比重
不過需要注意的是，trace 命令只會 trace 匹配到的函數(shù)里的子調(diào)用，并不會向下 trace 多層，如果需要 trace 多層，可以用正則匹配多個函數(shù)，如
$ trace -E com.huangxy.springstudy.controller.HelloController test|two
這下更清晰的定位到，導(dǎo)致耗時過長的方法是three()方法，定位到方法后，針對性的優(yōu)化耗時代碼塊即可
（版權(quán)歸原作者所有，侵刪）