Arthas - 線上某個接口忽然變慢了怎麼查

咱們模擬一個簡單的線上環境，有一個接口，有時候調用很慢，因爲調用過程當中涉及到多個方法的調用，因此比較難肯定究竟是哪一個方法比較慢，咱們能夠藉助Arthas來看看。

示例代碼

這段代碼中，trace方法會依次調用fun一、fun二、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,
]