问题
在程序运行过程中,发现有几个接口的响应时间特别长,需要快速定位到是哪一个方法的代码执行过程中出现了性能问题。
解决思路
已经确定是某个接口性能出现了问题,但是由于方法嵌套比较深,需要借助于算法定位到具体的方法。
Arthas的trace命令
使用arthas的trace命令,可以展示出整个方法的调用路径以及每一个方法的执行耗时。
命令: trace
类名
方法名
添加--skipJDKMethod false
参数可以输出JDK核心包中的方法及耗时。
添加 ‘ #cost >毫秒值 ’
参数,只会显示耗时超过该毫秒值的调用。
添加 -n 数值参数,最多显示该数值条数的数据。
所有监控都结束之后,输入stop结束监控,重置arthas增强的对象。(arthas底层使用动态代理的方式去增强这些对象从而获取他的调用时间,这样就增加了方法调用的开销降低了性能,如果不输入stop,增强的对象会在内存中保存,这个性能将会持续产生,所以最好是使用stop结束监控)
Arthas使用trace命令统计每个方法的执行时间
代码:
package com.itheima.jvmoptimize.performance;import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;import java.util.ArrayList;
import java.util.Random;@RestController
@RequestMapping("/performance")
public class PerformanceController {private Object obj1 = new Object();private Object obj2 = new Object();private Random random = new Random();@GetMapping("/1")public void test1(){while (true){}}@GetMapping("/deadlock1")public String test2() throws InterruptedException {synchronized (obj1){Thread.sleep(5000);synchronized (obj2){return "返回成功";}}}@GetMapping("/deadlock2")public String test3() throws InterruptedException {synchronized (obj2){Thread.sleep(5000);synchronized (obj1){return "返回成功";}}}@GetMapping("/slow")public void test4(int i) throws InterruptedException {if(i <= 0){return;}Thread.sleep(random.nextInt(2000));test5();}private void test5() throws InterruptedException {Thread.sleep(random.nextInt(1000));}@GetMapping("/profile1")public void test6() throws InterruptedException {ArrayList<Integer> objects = new ArrayList<>();for (Integer i = 0; i < 20000000; i++) {objects.add(i);}}@GetMapping("/profile2")public void test7() throws InterruptedException {ArrayList<Integer> objects = new ArrayList<>(20000000);for (Integer i = 0; i < 20000000; i++) {objects.add(i);}}}
启动程序(springboot)
启动arthas连接springboot应用程序(可自行百度查找):
输入命令进行监控慢请求的接口
trace com.itheima.jvmoptimize.performance.PerformanceController test4
打开测试软件请求:
http://localhost:8882/performance/slow?i=1
请求结果如下发现可以打印出请求比较慢的一些接口和信息
也可以使用命令查看更详细的显示
trace com.itheima.jvmoptimize.performance.PerformanceController test4 --skipJDKMethod false
再次使用postman发起请求
输出内容为:
可以看出命令窗口中输出了详细的方法和内容
重新发送请求将 i=1改为i=0(这样代码直接就return出去了)
发起请求 http://localhost:8882/performance/slow?i=0
可以发现依旧能打印出来信息
但是在线上环境这种端时间的请求我们不希望被arthas监控到,我们可以加个参数根据耗时时间打印出来内容
命令:
trace com.itheima.jvmoptimize.performance.PerformanceController test4 --skipJDKMethod false '#cost >1000'
再次发起请求
可以发现什么都没有打印出来
将参数改成i=1发现请求时间超过1s
如上图已经打印出来信息了
接下来可以输入-n 设置监控多少次请求
trace com.itheima.jvmoptimize.performance.PerformanceController test4 -n 1
打开postman发起两次请求看下结果:
命令窗口内容如下
会发现当前命令自动退出了,我们可以对它进行仔细分析
注意:arhtas 有一个小细节如下
启动一个项目,其中有个接口循环100w次
请求后发现接口响应时长为1.5秒:
我们启动arthas监控一下这个接口,在命令提示行输入命令
再次调用发现这个接口耗时增加到了2秒多
将代码中的循环调整为100次再次使用arthas监控
这个现象表现是arthas对循环较大的接口会产生较大的影响,循环越大影响响应时间越长,建议本地测试时适当减少循环次数
使用完记得输入stop命令进行关闭,这样将不会当前的内存和性能产生任何影响
watch命令
在使用trace定位到性能较低的方法之后,
使用watch命令监控该方法,可以获得更为详细的方法信息。
命令:watch 类名 方法名 '{params, returnobj}' '#cost>毫秒值' -x 2
'{params,returnobj}'
代表打印参数和返回值
-x 代表打印的结果中如果有嵌套(比如对象里有属性),最多只展开2层。允许设置的最大值为4。
测试如下
总结
1、通过arthas的trace命令,首先找到性能较差的具体方法,如果访问量比较大,建议设置最小的耗时,精确的找到耗时比较高的调用。
2、通过watch命令,查看此调用的参数和返回值,重点是参数,这样就可以在开发环境或者测试环境模拟类似的现象,通过debug找到具体的问题根源。
。允许设置的最大值为4。