咱们模仿一个简略的线上环境,有一个接口,有时候调用很慢,因为调用过程中波及到多个办法的调用,所以比拟难确定到底是哪个办法比较慢,咱们能够借助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;@RestControllerpublic 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.jarjava -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 tracePress 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|fun3Press 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 -bPress Q or Ctrl+C to abort.Affect(class count: 1 , method count: 1) cost in 28 ms, listenerId: 10method=com.dajun.arthas.controller.TestController.fun2 location=AtEnterts=2021-03-18 21:06:19; [cost=0.012014ms] result=@ArrayList[    @Object[][        @Integer[4],    ],    null,]