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 并追踪调用链路

1. java -jar arthas-boot.jar

2. 追踪调用链路：trace com.arthas.demo.controller.JvmThreadController methodTrace
   
   命令执行概览：Affect(class count: 1, method count: 1) 表示有1个类中的1个方法受到了追踪影响。这次操作耗时133毫秒，并分配了监听器ID为1。

3. 请求/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()方法。

4. ctrl+c退出当前追踪，并重新追踪methodTrace2()方法：trace com.arthas.demo.controller.JvmThreadController methodTrace2
   

5. 请求/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方法的调用链路就算走完了，我们可以清楚的追踪到每个方法以及子方法的耗时和调用链路，然后去分析整个接口的性能，最终去调优。

6. 再回顾一下整个追踪流程：
   
   trace 能方便的帮助你定位和发现因 RT 高而导致的性能问题缺陷，但其每次只能跟踪一级方法的调用链路，所以我们需要逐步分析，然后一级一级跟踪。

2、 函数执行数据观测：watch 命令