接口響應(yīng)慢該如何排查 接口慢的排查思路

不知道大家有沒有遇到這種情況，接口業(yè)務(wù)邏輯寫完后，用 postman 一調(diào)，發(fā)現(xiàn)接口響應(yīng)時間好長，不得不對接口進行優(yōu)化。

但是此時接口的代碼往往邏輯比較復(fù)雜，調(diào)用層次也比較多，很難定位到耗時較長的代碼塊

遇到這種情況大家都是如何定位耗時代碼塊的呢？

我看到很多人都是直接用System.currentTimeMillis()對代碼進行埋點

publicstaticvoidmain(String[]args){
LongstartTime=System.currentTimeMillis();
exec();
LongendTime=System.currentTimeMillis();
log.info("exec方法執(zhí)行耗時:{}ms",endTime-startTime);
}

或者用StopWatch打印方法耗時

publicstaticvoidmain(String[]args)throwsInterruptedException{
StopWatchstopWatch=newStopWatch();
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-Ohttps://arthas.aliyun.com/arthas-boot.jar
$java-jararthas-boot.jar

Arthas啟動的時候，會打印出當前運行的 java 進程

$java-jararthas-boot.jar
[INFO]JAVA_HOME:/Library/Java/JavaVirtualMachines/jdk1.8.0_351.jdk/Contents/Home/jre
[INFO]arthas-bootversion:3.6.9
[INFO]Foundexistingjavaprocess,pleasechooseoneandinputtheserialnumberoftheprocess,eg:1.ThenhitENTER.
*[1]:12512com.huangxy.springstudy.SpringStudyApplication
[2]:12511org.jetbrains.jps.cmdline.Launcher

然后可以選擇我們需要 attach 的 java 進程，這里我們選擇 1，然后按回車。Arthas 會 attach 到目標進程上，并輸出日志：

[INFO]arthashome:/Users/huangxiaoyu/.arthas/lib/3.6.9/arthas
[INFO]Trytoattachprocess12512
[INFO]Attachprocess12512success.
[INFO]arthas-clientconnect127.0.0.13658
,---.,------.,--------.,--.,--.,---.,---.
/O|.--.''--..--'|'--'|/O'.-'
|.-.||'--'.'|||.--.||.-.|`.`-.
||||||||||||||||.-'|
`--'`--'`--''--'`--'`--'`--'`--'`--'`-----'

wikihttps://arthas.aliyun.com/doc
tutorialshttps://arthas.aliyun.com/doc/arthas-tutorials.html
version3.6.9
main_classcom.huangxy.springstudy.SpringStudyApplication
pid12512
time2023-07-2509:14:22

到這里，Arthas 已經(jīng) attach 到我們的目標進程上了，我們嘗試使用dashboad命令，查看進程的信息

$dashboard
IDNAMEGROUPPRIORITYSTATE%CPUDELTA_TIMETIMEINTERRUPTDAEMON
36DestroyJavaVMmain5RUNNABLE0.00.0000:1.748falsefalse
-1C1CompilerThread3--1-0.00.0000:0.761falsetrue
-1VMPeriodicTaskThread--1-0.00.0000:0.237falsetrue
24http-nio-8081-exec-1main5WAITING0.00.0000:0.098falsetrue
-1VMThread--1-0.00.0000:0.071falsetrue
25http-nio-8081-exec-2main5WAITING0.00.0000:0.055falsetrue
54arthas-NettyHttpTelnetBootstrasystem5RUNNABLE0.00.0000:0.054falsetrue
-1GCtaskthread#8(ParallelGC)--1-0.00.0000:0.043falsetrue
-1GCtaskthread#1(ParallelGC)--1-0.00.0000:0.043falsetrue
-1GCtaskthread#7(ParallelGC)--1-0.00.0000:0.042falsetrue
-1GCtaskthread#6(ParallelGC)--1-0.00.0000:0.042falsetrue
-1GCtaskthread#0(ParallelGC)--1-0.00.0000:0.042falsetrue
-1GCtaskthread#9(ParallelGC)--1-0.00.0000:0.042falsetrue
-1GCtaskthread#2(ParallelGC)--1-0.00.0000:0.042falsetrue
-1GCtaskthread#3(ParallelGC)--1-0.00.0000:0.042falsetrue
-1GCtaskthread#5(ParallelGC)--1-0.00.0000:0.042falsetrue
-1GCtaskthread#4(ParallelGC)--1-0.00.0000:0.042falsetrue
MemoryusedtotalmaxusageGC
heap83M432M7282M1.14%gc.ps_scavenge.count4
ps_eden_space72M212M2688M2.69%gc.ps_scavenge.time(ms)24
ps_survivor_space0K21504K21504K0.00%gc.ps_marksweep.count2
ps_old_gen10M199M5461M0.20%gc.ps_marksweep.time(ms)61
nonheap53M56M-194.71%
code_cache6M7M240M2.87%
metaspace40M43M-194.45%
compressed_class_space5M5M1024M0.53%
direct16K16K-100.01%
mapped0K0K-0.00%
Runtime
os.nameMacOSX
os.version13.0.1
java.version1.8.0_351
java.home/Library/Java/JavaVirtualMachines/jdk1.8.0_351.jdk/Contents/
Home/jre
systemload.average3.80
processors12

可以看到dashboad命令會展示一個實時的數(shù)據(jù)面板，列出了我們平時比較關(guān)心的數(shù)據(jù)指標，如內(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
publicclassHelloController{

@GetMapping("/test")
publicStringtest()throwsInterruptedException{
one();
two();
return"hello";
}

privatevoidtwo()throwsInterruptedException{
Thread.sleep(20);
three();
}

privatevoidthree()throwsInterruptedException{
Thread.sleep(1000);
}

privatevoidone()throwsInterruptedException{
Thread.sleep(100);
}

}

啟動Arthas進程，并 attach 到我們的 springboot 項目上，接著使用trace命令跟蹤方法的調(diào)用情況

$tracecom.huangxy.springstudy.controller.HelloControllertest

trace方法第一個參數(shù)是要 attach 的類的路徑，第二個參數(shù)是方法名稱，接著我們調(diào)用一遍接口，就能看到 hello 方法的調(diào)用堆棧及其耗時

可以看到，這里耗時比較嚴重的是tow()方法，花了 1029ms，占了 90.73% 的比重

不過需要注意的是，trace 命令只會 trace 匹配到的函數(shù)里的子調(diào)用，并不會向下 trace 多層，如果需要 trace 多層，可以用正則匹配多個函數(shù)，如

$trace-E com.huangxy.springstudy.controller.HelloControllertest|two

這下更清晰的定位到，導(dǎo)致耗時過長的方法是three()方法，定位到方法后，針對性的優(yōu)化耗時代碼塊即可

審核編輯：劉清