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试试吧!

示例

# 简单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

  • 简单通过trace多个类、多个函数实现

      # 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]

  • 通过指定listenerId实现

    1. 打开终端1，trace run函数，记录终端的listenerId为12 
       [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

    2. 打开新的终端2，使用telnet localhost 3658连接Arthas，再trace primeFactors 指定listenerId为12，再查看终端1，发现输出如下

       ---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]