方法内部调用路径,并输出方法路径上的每个节点上耗时
trace
命令能主动搜索 class-pattern
/method-pattern
对应的方法调用路径,渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
参数名称 | 参数说明 |
---|---|
class-pattern | 类名表达式匹配 |
method-pattern | 方法名表达式匹配 |
condition-express | 条件表达式 |
[E] | 开启正则表达式匹配,默认为通配符匹配 |
[n:] |
命令执行次数 |
#cost |
方法执行耗时 |
[m <arg>] |
指定 Class 最大匹配数量,默认值为 50。长格式为[maxMatch <arg>] 。 |
条件表达式
,条件表达式
的构成主要由 ognl 表达式组成,所以你可以这样写"params[0]<0"
,只要是一个合法的 ognl 表达式,都能被正常支持。
请参考表达式核心变量中关于该节点的描述。
trace *StringUtils isBlank '#cost>100'
表示当执行时间超过 100ms 的时候,才会输出 trace 的结果。
提示
watch/stack/trace 这个三个命令都支持#cost
trace
能方便的帮助你定位和发现因 RT 高而导致的性能问题缺陷,但其每次只能跟踪一级方法的调用链路。参考:Trace 命令的实现原理trace java.lang.Thread getName
,参考 issue: #1610 ,考虑到不是非常必要场景,且修复有一定难度,因此当前暂不修复math-game
。
$ 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()
函数。
$ 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]
如果方法调用的次数很多,那么可以用-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.
--skipJDKMethod <value>
skip jdk method trace, default value true.--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 的调用路径,有助于在排查问题的时候,只关注异常情况trace
在执行的过程中本身是会有一定的性能开销,在统计的报告中并未像 JProfiler 一样预先减去其自身的统计开销。所以这统计出来有些许的不准,渲染路径上调用的类、方法越多,性能偏差越大。但还是能让你看清一些事情的。12.033735
的含义是:当前节点在当前步骤的耗时,单位为毫秒0,0,0ms,11
表示方法调用耗时,min,max,total,count
;throws Exception
表明该方法调用中存在异常返回trace -E com.test.ClassA|org.test.ClassB method1|method2|method3
--exclude-class-pattern
参数可以排除掉指定的类,比如:
trace javax.servlet.Filter * --exclude-class-pattern com.demo.TestFilter
提示
3.3.0 版本后支持。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)
,但不再打印更多的结果。
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
等命令也支持类似的功能。
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
没有被 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
i++
, getfield
等指令。提示
watch/trace/monitor/stack/tt 命令都支持-v
参数
-v
选项,则会打印Condition express
的具体值和执行结果,方便确认。