渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
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();
}
}
-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.
#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]
'#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 -E com.test.ClassA|org.test.ClassB method1|method2|method3
trace javax.servlet.Filter * --exclude-class-pattern com.demo.TestFilter
trace命令会对原始类进行加强,织入统计代码,使用stop停止Arthas会自动使用reset命令对已加强的类进行还原,以免浪费性能。