业务接口响应太慢，该如何排查？

👉 这是一个或许对你有用的社群

🐱 一对一交流/面试小册/简历优化/求职解惑，欢迎加入「芋道快速开发平台」知识星球。下面是星球提供的部分资料： 

• 《项目实战（视频）》：从书中学，往事上“练”

• 《互联网高频面试题》：面朝简历学习，春暖花开

• 《架构 x 系统设计》：摧枯拉朽，掌控面试高频场景题

• 《精进 Java 学习指南》：系统学习，互联网主流技术栈

• 《必读 Java 源码专栏》：知其然，知其所以然

👉这是一个或许对你有用的开源项目

国产 Star 破 10w+ 的开源项目，前端包括管理后台 + 微信小程序，后端支持单体和微服务架构。

功能涵盖 RBAC 权限、SaaS 多租户、数据权限、商城、支付、工作流、大屏报表、微信公众号等等功能：

• Boot 地址：https://gitee.com/zhijiantianya/ruoyi-vue-pro

• Cloud 地址：https://gitee.com/zhijiantianya/yudao-cloud

• 视频教程：https://doc.iocoder.cn

来源：huangxy

• Arthas 简介

• Arthas 快速开始

• 使用 Trace 命令统计方法耗时

---

不知道大家有没有遇到这种情况，接口业务逻辑写完后，用 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、线程等状态信息，还能实时查看方法调用入参、出参、方法调用耗时等

基于 Spring Boot + MyBatis Plus + Vue & Element 实现的后台管理系统 + 用户小程序，支持 RBAC 动态权限、多租户、数据权限、工作流、三方登录、支付、短信、商城等功能

• 项目地址：https://github.com/YunaiV/ruoyi-vue-pro

• 视频教程：https://doc.iocoder.cn/video/

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/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 已经 attach 到我们的目标进程上了，我们尝试使用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命令会展示一个实时的数据面板，列出了我们平时比较关心的数据指标，如内存使用量，gc 状态等

更多命令的使用，可以参考官网的命令列表

基于 Spring Cloud Alibaba + Gateway + Nacos + RocketMQ + Vue & Element 实现的后台管理系统 + 用户小程序，支持 RBAC 动态权限、多租户、数据权限、工作流、三方登录、支付、短信、商城等功能

• 项目地址：https://github.com/YunaiV/yudao-cloud

• 视频教程：https://doc.iocoder.cn/video/

使用 Trace 命令统计方法耗时

trace命令能主动搜索class-pattern／method-pattern对应的方法调用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路

比如下面接口

@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命令跟踪方法的调用情况

$ 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()方法，定位到方法后，针对性的优化耗时代码块即可

---

欢迎加入我的知识星球，全面提升技术能力。

加入方式，长按下方二维码噢：

星球的内容包括：项目实战、面试招聘、源码解析、学习路线。

文章有帮助的话，在看，转发吧。
谢谢支持哟 (*^__^*）