1、接口耗时查询：trace命令
trace 命令能主动搜索 class-pattern／method-pattern 对应的方法调用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
1.1 准备测试应用
新建一个 SpringBoot 应用，写一耗时久的代码：
@GetMapping("/methodTrace")
public String methodTrace() throws InterruptedException {
log.info("methodTrace start...");
Thread.sleep(1000);
this.methodTrace1();
this.methodTrace2();
log.info("methodTrace end...");
return "success";
}
private void methodTrace1() {
log.info("methodTrace1 start...");
}
private void methodTrace2() throws InterruptedException {
log.info("methodTrace2 start...");
Thread.sleep(2000);
this.methodTrace2_1();
this.methodTrace2_2();
}
private void methodTrace2_1() {
log.info("methodTrace2_1 start...");
}
private void methodTrace2_2() throws InterruptedException {
log.info("methodTrace2_2 start...");
this.methodTrace2_2_1();
}
private void methodTrace2_2_1() throws InterruptedException {
log.info("methodTrace2_2_1 start...");
Thread.sleep(3000);
}
1.2 运行项目
耗时 7 秒多，下面我们通过 trace 命令排查耗时久的罪魁祸首。
1.3 启动 Arthas 并追踪调用链路
-
java -jar arthas-boot.jar -
追踪调用链路：
trace com.arthas.demo.controller.JvmThreadController methodTrace
命令执行概览：Affect(class count: 1, method count: 1) 表示有1个类中的1个方法受到了追踪影响。这次操作耗时133毫秒，并分配了监听器ID为1。 -
请求
/methodTrace方法并观察调用详情
方法调用链：- methodTrace()调用：整体耗时约为6029毫秒
- 子调用：
- [0.07% 4.159334ms] org.slf4j.Logger:info() #99：首次日志输出调用，占总耗时的0.07%。
- [0.04% 2.476375ms] com.arthas.demo.controller.JvmThreadController:methodTrace1() #102：methodTrace1方法调用，耗时较短。
- [83.16% 5014.176042ms] com.arthas.demo.controller.JvmThreadController:methodTrace2() #103：methodTrace2方法调用，占据总耗时的83.16%。
- [0.02% 1.465ms] org.slf4j.Logger:info() #105：在方法链的末尾新增了一个日志输出调用，占总耗时的0.02%。
- 子调用：
结论：
- methodTrace()方法整体耗时约为6029毫秒，methodTrace()整体耗时减去下面子调用的耗时，得到的就是methodTrace()方法本身的耗时，约 1000ms，我们的代码 sleep 了1000ms，所以耗时基本准确。
- com.arthas.demo.controller.JvmThreadController:methodTrace2()方法占据总耗时的83.16%， 所以下一步要继续最终methodTrace2()方法。
- methodTrace()调用：整体耗时约为6029毫秒
-
ctrl+c退出当前追踪，并重新追踪methodTrace2()方法：trace com.arthas.demo.controller.JvmThreadController methodTrace2
-
请求
/methodTrace方法并观察调用详情
方法调用链的分析和第 3 步一样，就不多阐述了，可以看到上图红色字体，com.arthas.demo.controller.JvmThreadController:methodTrace2_2()耗时占 59.98% ，所以继续追踪trace com.arthas.demo.controller.JvmThreadController methodTrace2_2
继续追踪trace com.arthas.demo.controller.JvmThreadController methodTrace2_2_1
到这里，整个methodTrace方法的调用链路就算走完了，我们可以清楚的追踪到每个方法以及子方法的耗时和调用链路，然后去分析整个接口的性能，最终去调优。 -
再回顾一下整个追踪流程：
trace能方便的帮助你定位和发现因 RT 高而导致的性能问题缺陷，但其每次只能跟踪一级方法的调用链路，所以我们需要逐步分析，然后一级一级跟踪。
