Arthas - 线上某个接口突然变慢了怎么查
Posted 大军
tags:
篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了Arthas - 线上某个接口突然变慢了怎么查相关的知识,希望对你有一定的参考价值。
我们模拟一个简单的线上环境,有一个接口,有时候调用很慢,由于调用过程中涉及到多个方法的调用,所以比较难确定到底是哪个方法比较慢,我们可以借助Arthas来看看。
示例代码
这段代码中,trace方法会依次调用fun1、fun2、fun3方法。trace的入参是number,经过一系列假装很复杂的计算并传到下一个方法。这部分代码是基于springboot的。
package com.dajun.arthas.controller;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
import java.util.concurrent.TimeUnit;
@RestController
public class TestController {
@RequestMapping("/trace")
public String trace(int number) throws InterruptedException {
number++;
fun1(number);
return "Hello World!";
}
private void fun1(int number) throws InterruptedException {
TimeUnit.MILLISECONDS.sleep(10);
number++;
fun2(number);
}
private void fun2(int number) throws InterruptedException {
TimeUnit.MILLISECONDS.sleep(300);
number++;
fun3(number);
}
private void fun3(int number) throws InterruptedException {
TimeUnit.MILLISECONDS.sleep(20);
}
}
查看哪个方法
首先我们通过阿里云下载arthas,并运行jar包。
curl -O https://arthas.aliyun.com/arthas-boot.jar
java -jar arthas-boot.jar
运行后会出现下面的结果,然后我们选择1,就可以进行监听我们的应用程序。
如果不知道对应的PID,可以用jps或者其他方式查。
[root@ecs-4fbd Arthas]# java -jar arthas-boot.jar
[INFO] arthas-boot version: 3.5.0
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
* [1]: 15679 arthas-1.0-SNAPSHOT.jar
输入1后,我们用trace命令,格式是trace+空格+类名的全路径+空格+方法。执行结果如下,此时开始监听我们的方法。
[arthas@15679]$ trace com.dajun.arthas.controller.TestController trace
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 65 ms, listenerId: 1
我们在浏览器上输入地址http://192.168.0.101:8080/trace?number=2
并entrer。我们可以看到,trace方法执行了330.746895毫秒,fun1执行了330.40442毫秒。
[arthas@15976]$ trace com.dajun.arthas.controller.TestController trace
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 76 ms, listenerId: 1
`---ts=2021-03-18 17:29:22;thread_name=http-nio-8080-exec-1;id=11;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@27ae2fd0
`---[330.746895ms] com.dajun.arthas.controller.TestController:trace()
`---[330.40442ms] com.dajun.arthas.controller.TestController:fun1() #13
由于trace命令只会匹配当前的方法,以及下一级方法。所以我们上面的命令并没有很清楚的知道具体哪个方法比较慢,所以我们可以继续监听fun1方法,没发现问题再监听fun2,这样的话就比较麻烦。
Arthas提供了正则表匹配路径上的多个类和函数,所以我们执行以下的命令,在trace后面加-E,注意是大写,然后方法后面用|分隔,当然多个类也可以这样。
trace -E com.dajun.arthas.controller.TestController trace|fun1|fun2|fun3
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 4) cost in 68 ms, listenerId: 2
运行结果如下,我们可以看到fun2的耗时比较长。
[arthas@15976]$ trace -E com.dajun.arthas.controller.TestController trace|fun1|fun2|fun3
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 4) cost in 74 ms, listenerId: 2
`---ts=2021-03-18 17:29:57;thread_name=http-nio-8080-exec-2;id=12;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@27ae2fd0
`---[330.932104ms] com.dajun.arthas.controller.TestController:trace()
`---[330.826788ms] com.dajun.arthas.controller.TestController:fun1() #13
`---[330.757684ms] com.dajun.arthas.controller.TestController:fun1()
`---[320.577832ms] com.dajun.arthas.controller.TestController:fun2() #20
`---[320.489582ms] com.dajun.arthas.controller.TestController:fun2()
`---[20.301173ms] com.dajun.arthas.controller.TestController:fun3() #26
`---[20.191794ms] com.dajun.arthas.controller.TestController:fun3()
查看入参
watch
watch com.dajun.arthas.controller.TestController fun2 "{params,returnObj}" -x 2 -b
当我们重新调用接口时,看到传入了4。这个时候,我们就可以通过这个参数的值查看为什么这个方法执行这么慢了。
[arthas@15976]$ watch com.dajun.arthas.controller.TestController fun2 "{params,returnObj}" -x 2 -b
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 28 ms, listenerId: 10
method=com.dajun.arthas.controller.TestController.fun2 location=AtEnter
ts=2021-03-18 21:06:19; [cost=0.012014ms] result=@ArrayList[
@Object[][
@Integer[4],
],
null,
]
以上是关于Arthas - 线上某个接口突然变慢了怎么查的主要内容,如果未能解决你的问题,请参考以下文章