Arthas 使用 trace 查找耗时操作和调用链路

案例代码

package com.example.arthas.controller;

import com.example.arthas.view.Result;
import lombok.extern.slf4j.Slf4j;
import org.springframework.beans.factory.annotation.Value;
import org.springframework.util.CollectionUtils;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;

import java.util.List;

@Slf4j
@RestController
public class Test111Controller {

    @Value("${config.maxConn}")
    private Integer maxConn;

    @GetMapping("/test1")
    public Result test1(@RequestParam String key) throws InterruptedException {
        log.info("test1111111111111#{}", key);
        if ("ccc".equals(key)) {
            throw new RuntimeException("custom exception");
        }
        if ("bbb".equals(key)) {
            Thread.sleep(1000);
        }
        key = "ddd";
        List<String> list = (List<String>) CollectionUtils.arrayToList(new String[]{"aaa", "bbb", "ccc", key});
        return Result.builder().msg("success#" + maxConn).data(list).build();
    }

}

trace 命令

渲染和统计整个调用链路上的所有性能开销和追踪调用链路。

-n：命令执行次数。

trace com.example.arthas.controller.Test111Controller test1 -n 1

#22、#30等对应源码的行数。

输出：

curl http://127.0.0.1:8080/test1?key=aaa

[arthas@21776]$ trace com.example.arthas.controller.Test111Controller test1 -n 1
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 62 ms, listenerId: 1
`---ts=2021-02-12 11:42:38;thread_name=http-nio-8080-exec-2;id=1f;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@6a175569
    `---[2.556585ms] com.example.arthas.controller.Test111Controller:test1()
        +---[1.126399ms] org.slf4j.Logger:info() #22
        +---[0.026027ms] org.springframework.util.CollectionUtils:arrayToList() #30
        +---[0.024321ms] com.example.arthas.view.Result:builder() #31
        +---[0.04736ms] com.example.arthas.view.Result$ResultBuilder:msg() #95
        +---[0.075946ms] com.example.arthas.view.Result$ResultBuilder:data() #95
        `---[0.070399ms] com.example.arthas.view.Result$ResultBuilder:build() #95

Command execution times exceed limit: 1, so command will exit. You can set it with -n option.

trace 命令捕获异常

#24抛出异常，异常信息为custom exception。

curl http://127.0.0.1:8080/test1?key=ccc

[arthas@21776]$ trace com.example.arthas.controller.Test111Controller test1
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 41 ms, listenerId: 2
`---ts=2021-02-12 17:08:58;thread_name=http-nio-8080-exec-8;id=25;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@6a175569
    `---[6.513914ms] com.example.arthas.controller.Test111Controller:test1() [throws Exception]
        +---[1.055146ms] org.slf4j.Logger:info() #22
        `---throw:java.lang.RuntimeException #24 [custom exception]

trace 按耗时过滤

'#cost > 10'：会展示耗时大于10ms的调用路径。

trace --skipJDKMethod false com.example.arthas.controller.Test111Controller test1 '#cost > 10'

输出：

curl http://127.0.0.1:8080/test1?key=bbb

[arthas@21776]$ trace --skipJDKMethod false com.example.arthas.controller.Test111Controller test1 '#cost > 10' 
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 55 ms, listenerId: 3
`---ts=2021-02-12 17:02:54;thread_name=http-nio-8080-exec-4;id=21;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@6a175569
    `---[1007.546448ms] com.example.arthas.controller.Test111Controller:test1()
        +---[2.778451ms] org.slf4j.Logger:info() #22
        +---[0.057173ms] java.lang.String:equals() #23
        +---[0.01408ms] java.lang.String:equals() #26
        +---[1000.473599ms] java.lang.Thread:sleep() #27
        +---[0.199253ms] org.springframework.util.CollectionUtils:arrayToList() #30
        +---[0.258985ms] com.example.arthas.view.Result:builder() #31
        +---[0.10496ms] java.lang.StringBuilder:<init>() #57
        +---[min=0.332373ms,max=0.465492ms,total=0.797865ms,count=2] java.lang.StringBuilder:append() #57
        +---[0.115627ms] java.lang.StringBuilder:toString() #57
        +---[0.1472ms] com.example.arthas.view.Result$ResultBuilder:msg() #57
        +---[0.095147ms] com.example.arthas.view.Result$ResultBuilder:data() #57
        `---[0.06528ms] com.example.arthas.view.Result$ResultBuilder:build() #57

若不加--skipJDKMethod false只会看到方法test1耗时了1000ms

trace com.example.arthas.controller.Test111Controller test1 '#cost > 10'

具体输出如下：

curl http://127.0.0.1:8080/test1?key=bbb

[arthas@21776]$ trace com.example.arthas.controller.Test111Controller test1 '#cost > 10'
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 42 ms, listenerId: 4
`---ts=2021-02-12 17:01:09;thread_name=http-nio-8080-exec-3;id=20;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@6a175569
    `---[1000.246186ms] com.example.arthas.controller.Test111Controller:test1()
        +---[0.205653ms] org.slf4j.Logger:info() #22
        +---[0.0576ms] org.springframework.util.CollectionUtils:arrayToList() #30
        +---[0.0256ms] com.example.arthas.view.Result:builder() #31
        +---[0.030721ms] com.example.arthas.view.Result$ResultBuilder:msg() #95
        +---[0.020053ms] com.example.arthas.view.Result$ResultBuilder:data() #95
        `---[0.05632ms] com.example.arthas.view.Result$ResultBuilder:build() #95

更多

trace 多个类或者多个函数

trace -E com.test.ClassA|org.test.ClassB method1|method2|method3

排除掉指定的类

trace javax.servlet.Filter * --exclude-class-pattern com.demo.TestFilter

备注

trace命令会对原始类进行加强，织入统计代码，使用stop停止Arthas会自动使用reset命令对已加强的类进行还原，以免浪费性能。

参考

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