转载

arthas 的trace命令详解

#主要作用

方法内部调用路径,并输出方法路径上的每个节点上耗时

trace 命令能主动搜索 class-patternmethod-pattern 对应的方法调用路径,渲染和统计整个调用链路上的所有性能开销和追踪调用链路。

#参数说明

参数名称 参数说明
class-pattern 类名表达式匹配
method-pattern 方法名表达式匹配
condition-express 条件表达式
[E] 开启正则表达式匹配,默认为通配符匹配
[n:] 命令执行次数
#cost 方法执行耗时
[m <arg>] 指定 Class 最大匹配数量,默认值为 50。长格式为[maxMatch <arg>]
这里重点要说明的是条件表达式条件表达式的构成主要由 ognl 表达式组成,所以你可以这样写"params[0]<0",只要是一个合法的 ognl 表达式,都能被正常支持。 请参考表达式核心变量中关于该节点的描述。 很多时候我们只想看到某个方法的 rt 大于某个时间之后的 trace 结果,现在 Arthas 可以按照方法执行的耗时来进行过滤了,例如trace *StringUtils isBlank '#cost>100'表示当执行时间超过 100ms 的时候,才会输出 trace 的结果。

提示

watch/stack/trace 这个三个命令都支持#cost

#注意事项

  • trace 能方便的帮助你定位和发现因 RT 高而导致的性能问题缺陷,但其每次只能跟踪一级方法的调用链路。参考:Trace 命令的实现原理在新窗口打开
  • 3.3.0 版本后,可以使用动态 Trace 功能,不断增加新的匹配类,参考下面的示例。
  • 目前不支持 trace java.lang.Thread getName,参考 issue: #1610在新窗口打开 ,考虑到不是非常必要场景,且修复有一定难度,因此当前暂不修复

#使用参考

#启动 Demo

启动快速入门里的math-game

#trace 函数

$ trace demo.MathGame run
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 28 ms.
`---ts=2019-12-04 00:45:08;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[0.617465ms] demo.MathGame:run()
        `---[0.078946ms] demo.MathGame:primeFactors() #24 [throws Exception]

`---ts=2019-12-04 00:45:09;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[1.276874ms] demo.MathGame:run()
        `---[0.03752ms] demo.MathGame:primeFactors() #24 [throws Exception]

提示

结果里的 #24,表示在 run 函数里,在源文件的第24行调用了primeFactors()函数。

#指定 Class 匹配的最大数量

$ trace demo.MathGame run -m 1
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 412 ms, listenerId: 4
`---ts=2022-12-25 21:00:00;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@b4aac2
    `---[0.762093ms] demo.MathGame:run()
        `---[30.21% 0.230241ms] demo.MathGame:primeFactors() #46 [throws Exception]

`---ts=2022-12-25 21:00:10;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@b4aac2
    `---[0.315298ms] demo.MathGame:run()
        `---[13.95% 0.043995ms] demo.MathGame:primeFactors() #46 [throws Exception]

#trace 次数限制

如果方法调用的次数很多,那么可以用-n参数指定捕捉结果的次数。比如下面的例子里,捕捉到一次调用就退出命令。

$ trace demo.MathGame run -n 1
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 20 ms.
`---ts=2019-12-04 00:45:53;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[0.549379ms] demo.MathGame:run()
        +---[0.059839ms] demo.MathGame:primeFactors() #24
        `---[0.232887ms] demo.MathGame:print() #25

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

#包含 jdk 的函数

  • --skipJDKMethod <value> skip jdk method trace, default value true.
默认情况下,trace 不会包含 jdk 里的函数调用,如果希望 trace jdk 里的函数,需要显式设置--skipJDKMethod false
$ trace --skipJDKMethod false demo.MathGame run
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 60 ms.
`---ts=2019-12-04 00:44:41;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[1.357742ms] demo.MathGame:run()
        +---[0.028624ms] java.util.Random:nextInt() #23
        +---[0.045534ms] demo.MathGame:primeFactors() #24 [throws Exception]
        +---[0.005372ms] java.lang.StringBuilder:<init>() #28
        +---[0.012257ms] java.lang.Integer:valueOf() #28
        +---[0.234537ms] java.lang.String:format() #28
        +---[min=0.004539ms,max=0.005778ms,total=0.010317ms,count=2] java.lang.StringBuilder:append() #28
        +---[0.013777ms] java.lang.Exception:getMessage() #28
        +---[0.004935ms] java.lang.StringBuilder:toString() #28
        `---[0.06941ms] java.io.PrintStream:println() #28

`---ts=2019-12-04 00:44:42;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[3.030432ms] demo.MathGame:run()
        +---[0.010473ms] java.util.Random:nextInt() #23
        +---[0.023715ms] demo.MathGame:primeFactors() #24 [throws Exception]
        +---[0.005198ms] java.lang.StringBuilder:<init>() #28
        +---[0.006405ms] java.lang.Integer:valueOf() #28
        +---[0.178583ms] java.lang.String:format() #28
        +---[min=0.011636ms,max=0.838077ms,total=0.849713ms,count=2] java.lang.StringBuilder:append() #28
        +---[0.008747ms] java.lang.Exception:getMessage() #28
        +---[0.019768ms] java.lang.StringBuilder:toString() #28
        `---[0.076457ms] java.io.PrintStream:println() #28

#根据调用耗时过滤

$ trace demo.MathGame run '#cost > 10'
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 41 ms.
`---ts=2018-12-04 01:12:02;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[12.033735ms] demo.MathGame:run()
        +---[0.006783ms] java.util.Random:nextInt()
        +---[11.852594ms] demo.MathGame:primeFactors()
        `---[0.05447ms] demo.MathGame:print()

提示

只会展示耗时大于 10ms 的调用路径,有助于在排查问题的时候,只关注异常情况
  • 是不是很眼熟,没错,在 JProfiler 等收费软件中你曾经见识类似的功能,这里你将可以通过命令就能打印出指定调用路径。 友情提醒下,trace 在执行的过程中本身是会有一定的性能开销,在统计的报告中并未像 JProfiler 一样预先减去其自身的统计开销。所以这统计出来有些许的不准,渲染路径上调用的类、方法越多,性能偏差越大。但还是能让你看清一些事情的。
  • [12.033735ms] 的含义,12.033735 的含义是:当前节点在当前步骤的耗时,单位为毫秒
  • [0,0,0ms,11]xxx:yyy() [throws Exception],对该方法中相同的方法调用进行了合并,0,0,0ms,11 表示方法调用耗时,min,max,total,countthrows Exception 表明该方法调用中存在异常返回
  • 这里存在一个统计不准确的问题,就是所有方法耗时加起来可能会小于该监测方法的总耗时,这个是由于 Arthas 本身的逻辑会有一定的耗时

#trace 多个类或者多个函数

trace 命令只会 trace 匹配到的函数里的子调用,并不会向下 trace 多层。因为 trace 是代价比较贵的,多层 trace 可能会导致最终要 trace 的类和函数非常多。 可以用正则表匹配路径上的多个类和函数,一定程度上达到多层 trace 的效果。
trace -E com.test.ClassA|org.test.ClassB method1|method2|method3

#排除掉指定的类

使用 --exclude-class-pattern 参数可以排除掉指定的类,比如:
trace javax.servlet.Filter * --exclude-class-pattern com.demo.TestFilter

#动态 trace

提示

3.3.0 版本后支持。
打开终端 1,trace 上面 demo 里的run函数,可以看到打印出 listenerId: 1
[arthas@59161]$ trace demo.MathGame run
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 112 ms, listenerId: 1
`---ts=2020-07-09 16:48:11;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[1.389634ms] demo.MathGame:run()
        `---[0.123934ms] demo.MathGame:primeFactors() #24 [throws Exception]

`---ts=2020-07-09 16:48:12;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[3.716391ms] demo.MathGame:run()
        +---[3.182813ms] demo.MathGame:primeFactors() #24
        `---[0.167786ms] demo.MathGame:print() #25

现在想要深入子函数primeFactors,可以打开一个新终端 2,使用telnet localhost 3658连接上 arthas,再 trace primeFactors时,指定listenerId

[arthas@59161]$ trace demo.MathGame primeFactors --listenerId 1
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 34 ms, listenerId: 1

这时终端 2 打印的结果,说明已经增强了一个函数:Affect(class count: 1 , method count: 1),但不再打印更多的结果。

再查看终端 1,可以发现 trace 的结果增加了一层,打印了primeFactors函数里的内容:
`---ts=2020-07-09 16:49:29;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[0.492551ms] demo.MathGame:run()
        `---[0.113929ms] demo.MathGame:primeFactors() #24 [throws Exception]
            `---[0.061462ms] demo.MathGame:primeFactors()
                `---[0.001018ms] throw:java.lang.IllegalArgumentException() #46

`---ts=2020-07-09 16:49:30;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[0.409446ms] demo.MathGame:run()
        +---[0.232606ms] demo.MathGame:primeFactors() #24
        |   `---[0.1294ms] demo.MathGame:primeFactors()
        `---[0.084025ms] demo.MathGame:print() #25
通过指定listenerId的方式动态 trace,可以不断深入。另外 watch/tt/monitor等命令也支持类似的功能。

#trace 结果时间不准确问题

比如下面的结果里:0.705196 > (0.152743 + 0.145825)
$ trace demo.MathGame run -n 1
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 66 ms, listenerId: 1
`---ts=2021-02-08 11:27:36;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@232204a1
    `---[0.705196ms] demo.MathGame:run()
        +---[0.152743ms] demo.MathGame:primeFactors() #24
        `---[0.145825ms] demo.MathGame:print() #25
那么其它的时间消耗在哪些地方?
  1. 没有被 trace 到的函数。比如java.* 下的函数调用默认会忽略掉。通过增加--skipJDKMethod false参数可以打印出来。

     
    $ trace demo.MathGame run --skipJDKMethod false
    Press Q or Ctrl+C to abort.
    Affect(class count: 1 , method count: 1) cost in 35 ms, listenerId: 2
    `---ts=2021-02-08 11:27:48;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@232204a1
        `---[0.810591ms] demo.MathGame:run()
            +---[0.034568ms] java.util.Random:nextInt() #23
            +---[0.119367ms] demo.MathGame:primeFactors() #24 [throws Exception]
            +---[0.017407ms] java.lang.StringBuilder:<init>() #28
            +---[0.127922ms] java.lang.String:format() #57
            +---[min=0.01419ms,max=0.020221ms,total=0.034411ms,count=2] java.lang.StringBuilder:append() #57
            +---[0.021911ms] java.lang.Exception:getMessage() #57
            +---[0.015643ms] java.lang.StringBuilder:toString() #57
            `---[0.086622ms] java.io.PrintStream:println() #57
  2. 非函数调用的指令消耗。比如 i++getfield等指令。
  3. 在代码执行过程中,JVM 可能出现停顿,比如 GC,进入同步块等。

#使用 -v 参数打印更多信息

提示

watch/trace/monitor/stack/tt 命令都支持 -v 参数
当命令执行之后,没有输出结果。有两种可能:
  1. 匹配到的函数没有被执行
  2. 条件表达式结果是 false
但用户区分不出是哪种情况。 使用 -v选项,则会打印Condition express的具体值和执行结果,方便确认。
正文到此结束
Loading...