Java线上接口耗时分析神器 Arthas

布满荆棘的人生 2022-09-16 03:46 385阅读 0赞

### 文章目录 ###

*   *  背景
     *  问题
     *  Arthas
     *   *  github地址
         *  官网文档地址:
         *  说明
         *  安装
         *  运行Arthas
         *  trace命令的使用
         *  统计时间不准确问题
     *  总结

## 背景 ##

有时候我们在对线上接口作性能优化的时候需要找出一个方法的代码调用栈具体是那个方法或者哪行代码比较慢

最简单的方式就加log

// 使用spring提供的计时工具类
    		StopWatch sw = new StopWatch();
    
            sw.start("调用数据库1");
            TimeUnit.SECONDS.sleep(1);
            sw.stop();
    
            sw.start("调用数据库2");
            TimeUnit.SECONDS.sleep(2);
            sw.stop();
    
            sw.start("调用数据库3");
            TimeUnit.SECONDS.sleep(1);
            sw.stop();
    
            log.info("方法总耗时 {}", sw.getTotalTimeMillis());
            log.info("总任务数 {}", sw.getTaskCount());
            log.info(sw.prettyPrint());

打印结果如下

![image-20211014184831087][]  
可以看到最耗时的就是任务二，耗时50%，接着我们就可以对任务二中间的代码作优化

## 问题 ##

但是如果我们是线上接口呢？线上接口加log我们需要上线。然后部署合分支，发版。想想都很麻烦。有没有不需要加log就能知道各个方法的调用者的调用时间呢？答案是有的就是阿里开源的`Arthas`

## Arthas ##

### github地址 ###

https://github.com/alibaba/arthas

### 官网文档地址: ###

https://arthas.aliyun.com/doc/

### 说明 ###

![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAd2VpaHViZWF0cw_size_20_color_FFFFFF_t_70_g_se_x_16]  
这里的说明引用官方文档，有不懂的可以自己去看官方文档，这不是本文今天要介绍的重点

### 安装 ###

wget https://alibaba.github.io/arthas/arthas-boot.jar && java -jar arthas-boot.jar

### 运行Arthas ###

java -jar arthas-boot.jar

![image-20211014185927523][]  
运行完会显示我们运行的java进程的pid然后我们直接输入我们的pid然后就进入到`Arthas`里面了

### trace命令的使用 ###

接下来我们就介绍如何使用`trace`命令分析方法的耗时

使用起来很简单

比如我要分析类`OrderApplicationQueryService`中的`listPackage`方法的耗时

我们使用如下命令

trace com.test.query.OrderApplicationQueryService listPackage -n 1

格式就是： trace + 类所在包 + 类全称 + 空格 + 方法名

如果方法调用的次数很多，那么可以用`-n`参数指定捕捉结果的次数。比如上面的例子里，捕捉到一次调用就退出命令

然后我们执行上面的命令

![image-20211014190928635][]

到这里就是等待方法被调用。然后我们调用接口，让接口调用该方法，之后`Arthas`就会自动记录所有方法的调用时间了

![在这里插入图片描述][watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAd2VpaHViZWF0cw_size_20_color_FFFFFF_t_70_g_se_x_16 1]

可以看到`listPackageByCondition()`这个方法是比较耗时的

默认情况下，trace不会包含jdk里的函数调用，如果希望trace jdk里的函数，需要显式设置`--skipJDKMethod false`

上面的命令就变成如下方式了

trace --skipJDKMethod false com.test.query.OrderApplicationQueryService listPackage -n 1

执行上面命令，就可以看到jdk自带的函数调用耗时也打出来了，不过一般没啥必要。难道我们还能指望是jdk方法的耗时吗

![image-20211014192018538][]

其次也可以使用时间筛选命令，比如我们只展示方法调用耗时为>10ms的，则上面的命令变成如下方式

trace com.test.query.OrderApplicationQueryService listPackage '#cost > 10' -n 1

使用`#cost > 10'`即可

### 统计时间不准确问题 ###

需要注意的有时候trace命令可能存在时间不准确的问题，导致时间不准确的因素主要有如下几个原因：

1.  没有被trace到的函数,比如jdk自带的一些函数
2.  非函数调用的指令消耗。比如 i++, getfield等指令
3.  在代码执行过程中，JVM可能出现停顿，比如GC，进入同步块等
4.  trace 在执行的过程中本身是会有一定的性能开销，渲染路径上调用的类、方法越多，性能偏差越大(导致所有方法耗时加起来可能会小于监测方法的总耗时)

虽然有存在这些小问题，但是都并不算很影响方法耗时的判断

## 总结 ##

本文只是介绍了`Arthas`中耗时分析的命令，更多好用的命令请参考官网，对线上定位问题还是比较有帮助的

[image-20211014184831087]: /images/20220828/5236bd9e7049478a8620ee3eb36d0c81.png
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAd2VpaHViZWF0cw_size_20_color_FFFFFF_t_70_g_se_x_16]: /images/20220828/e7a6e45b41404ee0898b9ebca302ed8b.png
[image-20211014185927523]: /images/20220828/290f5238d510422994ed7dc6c8285416.png
[image-20211014190928635]: /images/20220828/6bb02aad00674b938e4e35c7ffcf7f63.png
[watermark_type_ZHJvaWRzYW5zZmFsbGJhY2s_shadow_50_text_Q1NETiBAd2VpaHViZWF0cw_size_20_color_FFFFFF_t_70_g_se_x_16 1]: /images/20220828/37358f94133c41b0b9be7b69c157c5c8.png
[image-20211014192018538]: /images/20220828/56412087430b4ada8a7f1a1e884956c5.png