不知道大家有没有遇到这种情况，接口业务逻辑写完后，用 postman 一调，发现接口响应时间好长，不得不对接口进行优化。但是此时接口的代码往往逻辑比较复杂，调用层次也比较多，很难定位到耗时较长的代码块。
遇到这种情况大家都是如何定位耗时代码块的呢？
我看到很多人都是直接用 System.currentTimeMillis()对代码进行埋点：
public static void main(String[] args) { Long startTime = System.currentTimeMillis(); exec(); Long endTime = System.currentTimeMillis(); log.info("exec 方法执行耗时:{}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());}
复制代码
这两种方法本质上是一样的，都是通过手动在代码块上进行埋点，打印出方法的耗时，该方法不仅费时费力，而且对代码有侵入，修复问题后删掉代码还是一个麻烦事。
下面介绍如果通过 Arthas 定位耗时代码块。
一、Arthas 简介
Arthas 是阿里开源的一款 Java 诊断工具，可以在无需重启 JVM 的情况下，实时查看应用 load、内存、gc、线程等状态信息，还能实时查看方法调用入参、出参、方法调用耗时等。
二、Arthas 快速开始
直接下载 Arthasjar 包，然后用 java -jar 命令启动即可：
$ curl -O https://arthas.aliyun.com/arthas-boot.jar$ java -jar arthas-boot.jar
复制代码
Arthas 启动的时候，会打印出当前运行的 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 到目标进程上，并输出日志：
[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/doctutorials https://arthas.aliyun.com/doc/arthas-tutorials.htmlversion 3.6.9main_class com.huangxy.springstudy.SpringStudyApplicationpid 12512time 2023-07-25 09:14:22
复制代码
到这里，Arthas 已经 attach 到我们的目标进程上了，我们尝试使用 dashboad 命令，查看进程的信息：
$ dashboardID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPT DAEMON36 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 true24 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 true25 http-nio-8081-exec-2 main 5 WAITING 0.0 0.000 0:0.055 false true54 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 trueMemory used total max usage GCheap 83M 432M 7282M 1.14% gc.ps_scavenge.count 4ps_eden_space 72M 212M 2688M 2.69% gc.ps_scavenge.time(ms) 24ps_survivor_space 0K 21504K 21504K 0.00% gc.ps_marksweep.count 2ps_old_gen 10M 199M 5461M 0.20% gc.ps_marksweep.time(ms) 61nonheap 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%Runtimeos.name Mac OS Xos.version 13.0.1java.version 1.8.0_351java.home /Library/Java/JavaVirtualMachines/jdk1.8.0_351.jdk/Contents/ Home/jresystemload.average 3.80processors 12
复制代码
可以看到 dashboad 命令会展示一个实时的数据面板，列出了我们平时比较关心的数据指标，如内存使用量，gc 状态等。
三、使用 Trace 命令统计方法耗时
trace 命令能主动搜索 class-pattern／method-pattern 对应的方法调用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
比如下面接口：
@RestControllerpublic 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 命令跟踪方法的调用情况：
$ trace com.huangxy.springstudy.controller.HelloController test
复制代码
trace 方法第一个参数是要 attach 的类的路径，第二个参数是方法名称，接着我们调用一遍接口，就能看到 hello 方法的调用堆栈及其耗时
可以看到，这里耗时比较严重的是 tow()方法，花了 1029ms，占了 90.73% 的比重。
不过需要注意的是，trace 命令只会 trace 匹配到的函数里的子调用，并不会向下 trace 多层，如果需要 trace 多层，可以用正则匹配多个函数，如：
$ trace -E com.huangxy.springstudy.controller.HelloController test|two
复制代码
这下更清晰的定位到，导致耗时过长的方法是 three()方法，定位到方法后，针对性的优化耗时代码块即可。
评论