Arthas手册trace
查看方法内部调用路径，并输出方法路径上的每个节点上耗时。 trace命令能主动搜索class-pattern／method-pattern对应的方法调用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
命令选项
| 命令选项 | 描述 |
|---|---|
| --exclude-class-pattern <pattern> | 排除class模式 |
| -n, --limits <number> | 监控执行次数 |
| --listenerId <id> | 特殊的监控id |
| -p, --path <path> | 路径跟踪模式匹配 |
| -E, --regex | 开启正则匹配，默认为通配符匹配 |
| --skipJDKMethod | 跳过jdk方法跟踪，默认值true |
| -v, --verbose | 打印debug信息 |
| -h, --help | 帮助 |
| <class-pattern> | 类匹配模式 |
| <method-pattern> | 方法匹配模式 |
| <condition-express> | ognl条件表达式 |
提示
有的时候trace的结果发现方法耗时不高，但是总耗时高，加上--skipJDKMethod false试试吧!
示例
bash
# 简单trace
[arthas@20276]$ trace demo.MathGame run
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 29 ms, listenerId: 5
`---ts=2023-03-30 16:48:08;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[0.8382ms] demo.MathGame:run()
+---[3.90% 0.0327ms ] demo.MathGame:primeFactors() #24
`---[75.20% 0.6303ms ] demo.MathGame:print() #25
`---ts=2023-03-30 16:48:09;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[2.801ms] demo.MathGame:run()
`---[3.55% 0.0995ms ] demo.MathGame:primeFactors() #24 [throws Exception]
# 限制trace次数
[arthas@20276]$ trace demo.MathGame run -n 2
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 18 ms, listenerId: 6
`---ts=2023-03-30 16:48:48;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[0.7409ms] demo.MathGame:run()
+---[5.24% 0.0388ms ] demo.MathGame:primeFactors() #24
`---[78.93% 0.5848ms ] demo.MathGame:print() #25
`---ts=2023-03-30 16:48:49;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[1.0571ms] demo.MathGame:run()
+---[4.75% 0.0502ms ] demo.MathGame:primeFactors() #24
`---[91.07% 0.9627ms ] demo.MathGame:print() #25
Command execution times exceed limit: 2, so command will exit. You can set it with -n option.
# 包含jdk方法
[arthas@20276]$ trace demo.MathGame run -n 2 --skipJDKMethod false
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 24 ms, listenerId: 7
`---ts=2023-03-30 16:49:09;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[2.7671ms] demo.MathGame:run()
+---[0.54% 0.015ms ] java.util.Random:nextInt() #23
+---[1.86% 0.0514ms ] demo.MathGame:primeFactors() #24 [throws Exception]
+---[0.17% 0.0047ms ] java.lang.StringBuilder:<init>() #28
+---[2.80% 0.0776ms ] java.lang.String:format() #28
+---[0.29% min=0.0027ms,max=0.0054ms,total=0.0081ms,count=2] java.lang.StringBuilder:append() #28
+---[0.21% 0.0057ms ] java.lang.Exception:getMessage() #28
+---[0.16% 0.0044ms ] java.lang.StringBuilder:toString() #28
`---[85.73% 2.3721ms ] java.io.PrintStream:println() #28
`---ts=2023-03-30 16:49:10;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[0.6678ms] demo.MathGame:run()
+---[1.14% 0.0076ms ] java.util.Random:nextInt() #23
+---[9.01% 0.0602ms ] demo.MathGame:primeFactors() #24
`---[83.96% 0.5607ms ] demo.MathGame:print() #25
Command execution times exceed limit: 2, so command will exit. You can set it with -n option.
# 根据耗时过滤
[arthas@20276]$ trace demo.MathGame run -n 2 --skipJDKMethod false '#cost > 1'
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 28 ms, listenerId: 8
`---ts=2023-03-30 16:50:17;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[1.1709ms] demo.MathGame:run()
+---[11.06% 0.1295ms ] java.util.Random:nextInt() #23
+---[10.11% 0.1184ms ] demo.MathGame:primeFactors() #24 [throws Exception]
+---[0.20% 0.0023ms ] java.lang.StringBuilder:<init>() #28
+---[5.88% 0.0689ms ] java.lang.String:format() #28
+---[0.30% min=0.0013ms,max=0.0022ms,total=0.0035ms,count=2] java.lang.StringBuilder:append() #28
+---[0.33% 0.0039ms ] java.lang.Exception:getMessage() #28
+---[0.16% 0.0019ms ] java.lang.StringBuilder:toString() #28
`---[28.89% 0.3383ms ] java.io.PrintStream:println() #28
`---ts=2023-03-30 16:50:19;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[3.79ms] demo.MathGame:run()
+---[0.27% 0.0102ms ] java.util.Random:nextInt() #23
+---[1.78% 0.0676ms ] demo.MathGame:primeFactors() #24 [throws Exception]
+---[0.03% 0.0011ms ] java.lang.StringBuilder:<init>() #28
+---[0.97% 0.0366ms ] java.lang.String:format() #28
+---[0.05% min=0.001ms,max=0.001ms,total=0.002ms,count=2] java.lang.StringBuilder:append() #28
+---[0.03% 0.0012ms ] java.lang.Exception:getMessage() #28
+---[0.02% 9.0E-4ms ] java.lang.StringBuilder:toString() #28
`---[93.92% 3.5595ms ] java.io.PrintStream:println() #28
Command execution times exceed limit: 2, so command will exit. You can set it with -n option.
# 排除指定类
[arthas@20276]$ trace javax.servlet.Filter * --exclude-class-pattern com.demo.TestFilter# 简单trace
[arthas@20276]$ trace demo.MathGame run
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 29 ms, listenerId: 5
`---ts=2023-03-30 16:48:08;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[0.8382ms] demo.MathGame:run()
+---[3.90% 0.0327ms ] demo.MathGame:primeFactors() #24
`---[75.20% 0.6303ms ] demo.MathGame:print() #25
`---ts=2023-03-30 16:48:09;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[2.801ms] demo.MathGame:run()
`---[3.55% 0.0995ms ] demo.MathGame:primeFactors() #24 [throws Exception]
# 限制trace次数
[arthas@20276]$ trace demo.MathGame run -n 2
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 18 ms, listenerId: 6
`---ts=2023-03-30 16:48:48;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[0.7409ms] demo.MathGame:run()
+---[5.24% 0.0388ms ] demo.MathGame:primeFactors() #24
`---[78.93% 0.5848ms ] demo.MathGame:print() #25
`---ts=2023-03-30 16:48:49;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[1.0571ms] demo.MathGame:run()
+---[4.75% 0.0502ms ] demo.MathGame:primeFactors() #24
`---[91.07% 0.9627ms ] demo.MathGame:print() #25
Command execution times exceed limit: 2, so command will exit. You can set it with -n option.
# 包含jdk方法
[arthas@20276]$ trace demo.MathGame run -n 2 --skipJDKMethod false
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 24 ms, listenerId: 7
`---ts=2023-03-30 16:49:09;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[2.7671ms] demo.MathGame:run()
+---[0.54% 0.015ms ] java.util.Random:nextInt() #23
+---[1.86% 0.0514ms ] demo.MathGame:primeFactors() #24 [throws Exception]
+---[0.17% 0.0047ms ] java.lang.StringBuilder:<init>() #28
+---[2.80% 0.0776ms ] java.lang.String:format() #28
+---[0.29% min=0.0027ms,max=0.0054ms,total=0.0081ms,count=2] java.lang.StringBuilder:append() #28
+---[0.21% 0.0057ms ] java.lang.Exception:getMessage() #28
+---[0.16% 0.0044ms ] java.lang.StringBuilder:toString() #28
`---[85.73% 2.3721ms ] java.io.PrintStream:println() #28
`---ts=2023-03-30 16:49:10;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[0.6678ms] demo.MathGame:run()
+---[1.14% 0.0076ms ] java.util.Random:nextInt() #23
+---[9.01% 0.0602ms ] demo.MathGame:primeFactors() #24
`---[83.96% 0.5607ms ] demo.MathGame:print() #25
Command execution times exceed limit: 2, so command will exit. You can set it with -n option.
# 根据耗时过滤
[arthas@20276]$ trace demo.MathGame run -n 2 --skipJDKMethod false '#cost > 1'
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 28 ms, listenerId: 8
`---ts=2023-03-30 16:50:17;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[1.1709ms] demo.MathGame:run()
+---[11.06% 0.1295ms ] java.util.Random:nextInt() #23
+---[10.11% 0.1184ms ] demo.MathGame:primeFactors() #24 [throws Exception]
+---[0.20% 0.0023ms ] java.lang.StringBuilder:<init>() #28
+---[5.88% 0.0689ms ] java.lang.String:format() #28
+---[0.30% min=0.0013ms,max=0.0022ms,total=0.0035ms,count=2] java.lang.StringBuilder:append() #28
+---[0.33% 0.0039ms ] java.lang.Exception:getMessage() #28
+---[0.16% 0.0019ms ] java.lang.StringBuilder:toString() #28
`---[28.89% 0.3383ms ] java.io.PrintStream:println() #28
`---ts=2023-03-30 16:50:19;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c
`---[3.79ms] demo.MathGame:run()
+---[0.27% 0.0102ms ] java.util.Random:nextInt() #23
+---[1.78% 0.0676ms ] demo.MathGame:primeFactors() #24 [throws Exception]
+---[0.03% 0.0011ms ] java.lang.StringBuilder:<init>() #28
+---[0.97% 0.0366ms ] java.lang.String:format() #28
+---[0.05% min=0.001ms,max=0.001ms,total=0.002ms,count=2] java.lang.StringBuilder:append() #28
+---[0.03% 0.0012ms ] java.lang.Exception:getMessage() #28
+---[0.02% 9.0E-4ms ] java.lang.StringBuilder:toString() #28
`---[93.92% 3.5595ms ] java.io.PrintStream:println() #28
Command execution times exceed limit: 2, so command will exit. You can set it with -n option.
# 排除指定类
[arthas@20276]$ trace javax.servlet.Filter * --exclude-class-pattern com.demo.TestFilter1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
动态trace
简单通过trace多个类、多个函数实现
bash# trace多个类或者多个函数 [arthas@20276]$ trace -E demo.MathGame run|primeFactors Press Q or Ctrl+C to abort. Affect(class count: 1 , method count: 2) cost in 31 ms, listenerId: 11 `---ts=2023-03-30 16:55:20;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[1.691ms] demo.MathGame:run() +---[71.03% 1.2012ms ] demo.MathGame:primeFactors() #24 | `---[97.34% 1.1693ms ] demo.MathGame:primeFactors() `---[23.77% 0.402ms ] demo.MathGame:print() #25 `---ts=2023-03-30 16:55:21;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[0.9092ms] demo.MathGame:run() `---[23.78% 0.2162ms ] demo.MathGame:primeFactors() #24 [throws Exception] `---[90.43% 0.1955ms ] demo.MathGame:primeFactors() [throws Exception] `---throw:java.lang.IllegalArgumentException #46 [number is: -192405, need >= 2] `---ts=2023-03-30 16:55:22;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[3.4903ms] demo.MathGame:run() `---[2.93% 0.1024ms ] demo.MathGame:primeFactors() #24 [throws Exception] `---[78.71% 0.0806ms ] demo.MathGame:primeFactors() [throws Exception] `---throw:java.lang.IllegalArgumentException #46 [number is: -162783, need >= 2] `---ts=2023-03-30 16:55:23;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[2.6368ms] demo.MathGame:run() `---[4.06% 0.1071ms ] demo.MathGame:primeFactors() #24 [throws Exception] `---[67.97% 0.0728ms ] demo.MathGame:primeFactors() [throws Exception] `---throw:java.lang.IllegalArgumentException #46 [number is: -53374, need >= 2]# trace多个类或者多个函数 [arthas@20276]$ trace -E demo.MathGame run|primeFactors Press Q or Ctrl+C to abort. Affect(class count: 1 , method count: 2) cost in 31 ms, listenerId: 11 `---ts=2023-03-30 16:55:20;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[1.691ms] demo.MathGame:run() +---[71.03% 1.2012ms ] demo.MathGame:primeFactors() #24 | `---[97.34% 1.1693ms ] demo.MathGame:primeFactors() `---[23.77% 0.402ms ] demo.MathGame:print() #25 `---ts=2023-03-30 16:55:21;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[0.9092ms] demo.MathGame:run() `---[23.78% 0.2162ms ] demo.MathGame:primeFactors() #24 [throws Exception] `---[90.43% 0.1955ms ] demo.MathGame:primeFactors() [throws Exception] `---throw:java.lang.IllegalArgumentException #46 [number is: -192405, need >= 2] `---ts=2023-03-30 16:55:22;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[3.4903ms] demo.MathGame:run() `---[2.93% 0.1024ms ] demo.MathGame:primeFactors() #24 [throws Exception] `---[78.71% 0.0806ms ] demo.MathGame:primeFactors() [throws Exception] `---throw:java.lang.IllegalArgumentException #46 [number is: -162783, need >= 2] `---ts=2023-03-30 16:55:23;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[2.6368ms] demo.MathGame:run() `---[4.06% 0.1071ms ] demo.MathGame:primeFactors() #24 [throws Exception] `---[67.97% 0.0728ms ] demo.MathGame:primeFactors() [throws Exception] `---throw:java.lang.IllegalArgumentException #46 [number is: -53374, need >= 2]1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27通过指定listenerId实现
打开终端1，trace run函数，记录终端的listenerId为12
bash[arthas@20276]$ trace demo.MathGame run Press Q or Ctrl+C to abort. Affect(class count: 1 , method count: 1) cost in 18 ms, listenerId: 12 `---ts=2023-03-30 17:01:34;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[1.404ms] demo.MathGame:run() +---[18.89% 0.2652ms ] demo.MathGame:primeFactors() #24 ` ---[70.06% 0.9836ms ] demo.MathGame:print() #25 `---ts=2023-03-30 17:01:35;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[0.4216ms] demo.MathGame:run() +---[5.43% 0.0229ms ] demo.MathGame:primeFactors() #24 `---[90.51% 0.3816ms ] demo.MathGame:print() #25[arthas@20276]$ trace demo.MathGame run Press Q or Ctrl+C to abort. Affect(class count: 1 , method count: 1) cost in 18 ms, listenerId: 12 `---ts=2023-03-30 17:01:34;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[1.404ms] demo.MathGame:run() +---[18.89% 0.2652ms ] demo.MathGame:primeFactors() #24 ` ---[70.06% 0.9836ms ] demo.MathGame:print() #25 `---ts=2023-03-30 17:01:35;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[0.4216ms] demo.MathGame:run() +---[5.43% 0.0229ms ] demo.MathGame:primeFactors() #24 `---[90.51% 0.3816ms ] demo.MathGame:print() #251
2
3
4
5
6
7
8
9
10
11
12打开新的终端2，使用
telnet localhost 3658连接Arthas，再trace primeFactors 指定listenerId为12，再查看终端1，发现输出如下bash---ts=2023-03-30 17:05:30;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[1.0965ms] demo.MathGame:run() `---[9.75% 0.1069ms ] demo.MathGame:primeFactors() #24 [throws Exception] `---[84.00% 0.0898ms ] demo.MathGame:primeFactors() [throws Exception] `---throw:java.lang.IllegalArgumentException #46 [number is: -79404, need >= 2] `---ts=2023-03-30 17:05:31;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[2.8765ms] demo.MathGame:run() +---[2.30% 0.0663ms ] demo.MathGame:primeFactors() #24 | `---[89.44% 0.0593ms ] demo.MathGame:primeFactors() `---[97.02% 2.7907ms ] demo.MathGame:print() #25 `---ts=2023-03-30 17:05:32;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[1.1646ms] demo.MathGame:run() `---[6.11% 0.0711ms ] demo.MathGame:primeFactors() #24 [throws Exception] `---[76.79% 0.0546ms ] demo.MathGame:primeFactors() [throws Exception] `---throw:java.lang.IllegalArgumentException #46 [number is: -24904, need >= 2]---ts=2023-03-30 17:05:30;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[1.0965ms] demo.MathGame:run() `---[9.75% 0.1069ms ] demo.MathGame:primeFactors() #24 [throws Exception] `---[84.00% 0.0898ms ] demo.MathGame:primeFactors() [throws Exception] `---throw:java.lang.IllegalArgumentException #46 [number is: -79404, need >= 2] `---ts=2023-03-30 17:05:31;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[2.8765ms] demo.MathGame:run() +---[2.30% 0.0663ms ] demo.MathGame:primeFactors() #24 | `---[89.44% 0.0593ms ] demo.MathGame:primeFactors() `---[97.02% 2.7907ms ] demo.MathGame:print() #25 `---ts=2023-03-30 17:05:32;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@6d06d69c `---[1.1646ms] demo.MathGame:run() `---[6.11% 0.0711ms ] demo.MathGame:primeFactors() #24 [throws Exception] `---[76.79% 0.0546ms ] demo.MathGame:primeFactors() [throws Exception] `---throw:java.lang.IllegalArgumentException #46 [number is: -24904, need >= 2]1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17