Arthas实战（5）- 项目性能调优

String NUll

已于 2024-07-22 14:54:06 修改

阅读量1.2k

点赞数 22

分类专栏： # Arthas 文章标签： Arthas

于 2024-07-05 17:46:03 首次发布

本文链接：https://blog.youkuaiyun.com/java_liuyuan/article/details/140212569

版权

Arthas 专栏收录该内容

5 篇文章

订阅专栏

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()方法。
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 高而导致的性能问题缺陷，但其每次只能跟踪一级方法的调用链路，所以我们需要逐步分析，然后一级一级跟踪。

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

让你能方便的观察到指定函数的调用情况。能观察到的范围为：返回值、抛出异常、入参，通过编写 OGNL 表达式进行对应变量的查看。

2.1 准备测试应用

新建一个 SpringBoot 应用，写一段有出入参的代码：

@PostMapping("/methodWatch")
    public MethodWatchModel methodWatch(@RequestBody MethodWatchRequest request) throws InterruptedException {

        if (Objects.equals("gay", request.getName())) {
            throw new RuntimeException("name is gay");
        }
        if (request.getAge() == 18) {
            Thread.sleep(1000);
        }

        MethodWatchModel model = new MethodWatchModel();
        model.setName(request.getName());
        model.setAge(request.getAge());
        model.setAddress(request.getAddress());
        return model;
    }

    @Data
    static class MethodWatchRequest implements Serializable {
        private String name;
        private Integer age;
        private String address;
    }
    @Data
    static class MethodWatchModel implements Serializable {
        private String name;
        private Integer age;
        private String address;
    }

2.2 `watch`命令使用参考

2.2.1 观察函数调用时的参数、this 对象和返回值

watch com.arthas.demo.controller.JvmThreadController methodWatch "{params,target,returnObj}" -x 2
等同于：
watch com.arthas.demo.controller.JvmThreadController methodWatch -x 2

上面的命令不会打印异常信息，如果需要打印异常信息，用这个：
watch com.arthas.demo.controller.JvmThreadController methodWatch '{params,target,returnObj,throwExp}' -x 2

在这里插入图片描述

命令解释：
- watch：这是Arthas的命令，用于监控方法调用。
- com.arthas.demo.controller.JvmThreadController：这是您要监控的类的全限定名。
- methodWatch：假设这是您要监控的方法名，应替换为您实际想要监控的方法名称。
- “{params,target,returnObj}”：这部分定义了在方法调用时要输出的信息。params表示方法的所有参数，target表示调用该方法的对象实例，returnObj表示方法的返回值。这些信息将在方法调用时被打印出来。
- -x 表示遍历深度，可以调整来打印具体的参数和结果内容，默认值是 1。-x最大值是 4，防止展开结果占用太多内存。用户可以在ognl表达式里指定更具体的 field。

响应解释：
- 监控设置：Affect(class count: 1 , method count: 1) cost in 128 ms, listenerId: 1 表示监控设置影响了1个类中的1个方法，耗时128毫秒，分配的监听器ID为1。
- 监控触发：method=com.arthas.demo.controller.JvmThreadController.methodWatch location=AtExit 显示监控发生在methodWatch方法退出时。
- 监控时间戳：监控记录的时间戳为2024-07-08 10:40:36。
- 监控结果：监控结果包含三个部分：
  - @MethodWatchRequest：表示方法调用时传递的参数，这里是一个JvmThreadController.MethodWatchRequest实例，包含name=ly，age=17，address=中国。
  - @JvmThreadController：表示调用该方法的对象实例，可以看到其中包含了日志实例、空的memoryList、以及两个资源对象resource1和resource2。
  - @MethodWatchModel：表示方法的返回值或处理的结果，这里包含了name、age、address三个字段的值。
  - 性能指标：[cost=0.770417ms] 显示整个监控操作耗时约0.77毫秒。

2.2.2 观察特定参数和返回值

只查看入参的 name 和 age 以及出参对象：
watch com.arthas.demo.controller.JvmThreadController methodWatch "{params[0].name,params[0].age,returnObj}" -x 2
只查看入参的 name 和 age 以及出参的 address：
watch com.arthas.demo.controller.JvmThreadController methodWatch "{params[0].name,params[0].age,returnObj.address}" -x 2

2.2.3 条件表达式

按照耗时进行过滤：
watch com.arthas.demo.controller.JvmThreadController methodWatch '{params,target,returnObj}' '#cost>200' -x 2
- #cost>200(单位是ms)表示只有当耗时大于 200ms 时才会输出，过滤掉执行时间小于 200ms 的调用
- age = 18时，程序会睡 1000ms，耗时大于 200ms ，所以可以输出参数
抛出异常时才触发：
watch com.arthas.demo.controller.JvmThreadController methodWatch "{params,throwExp}" -e -x 2
- -e表示抛出异常时才触发,express 中，表示异常信息的变量是throwExp
- name 等于 gay 时，会触发异常，所以可以输出参数

3、反编译指定已加载类的源码：`jad` 命令

jad com.arthas.demo.controller.JvmThreadController methodWatch
在这里插入图片描述

ClassLoader: 列出了类加载器信息，显示JvmThreadController类是由Launcher $A ppCl a ss L o a d er 加载的，其父类加载器是 L a u n c h er$ ExtClassLoader。这表明类路径下的类是由应用类加载器加载的，而扩展类库则由扩展类加载器加载。
Location: 指出了JvmThreadController类的物理位置，位于/Users/xxx/IdeaProjects/parent-demo/arthas-demo/target/classes/目录下，这通常是Maven项目构建后class文件的存放位置。
源码以及行号
Affect(row-cnt:3) cost in 1199 ms.，这表示Arthas执行了某种操作，影响了3行数据，耗时1199毫秒。