阅读全文

⭐⭐⭐ Spring Boot 项目实战	⭐⭐⭐ Spring Cloud 项目实战
《Dubbo 实现原理与源码解析 —— 精品合集》	《Netty 实现原理与源码解析 —— 精品合集》
《Spring 实现原理与源码解析 —— 精品合集》	《MyBatis 实现原理与源码解析 —— 精品合集》
《Spring MVC 实现原理与源码解析 —— 精品合集》	《数据库实体设计合集》
《Spring Boot 实现原理与源码解析 —— 精品合集》	《Java 面试题 + Java 学习指南》

摘要: 原创出处 huangxy 「huangxy」欢迎转载，保留摘要，谢谢！

🙂🙂🙂关注**微信公众号：【芋道源码】**有福利：

RocketMQ / MyCAT / Sharding-JDBC 所有源码分析文章列表

RocketMQ / MyCAT / Sharding-JDBC 中文注释源码 GitHub 地址

您对于源码的疑问每条留言都将得到认真回复。甚至不知道如何读源码也可以请教噢。

新的源码解析文章实时收到通知。每周更新一篇左右。

认真的源码交流微信群。

不知道大家有没有遇到这种情况，接口业务逻辑写完后，用 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/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 状态等

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

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

芋道源码 —— 纯源码解析博客

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

Arthas 简介

Arthas 快速开始

使用 Trace 命令统计方法耗时