trace

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

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

参数说明

参数名称 参数说明
class-pattern 类名表达式匹配
method-pattern 方法名表达式匹配
condition-express 条件表达式
[E] 开启正则表达式匹配，默认为通配符匹配
[n:] 命令执行次数
#cost 方法执行耗时

这里重点要说明的是观察表达式，观察表达式的构成主要由 ognl 表达式组成，所以你可以这样写"{params,returnObj}"，只要是一个合法的 ognl 表达式，都能被正常支持。

观察的维度也比较多，主要体现在参数 advice 的数据结构上。Advice 参数最主要是封装了通知节点的所有信息。

请参考表达式核心变量中关于该节点的描述。

很多时候我们只想看到某个方法的rt大于某个时间之后的trace结果，现在Arthas可以按照方法执行的耗时来进行过滤了，例如trace *StringUtils isBlank '#cost>100'表示当执行时间超过100ms的时候，才会输出trace的结果。

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

注意事项

trace 能方便的帮助你定位和发现因 RT 高而导致的性能问题缺陷，但其每次只能跟踪一级方法的调用链路。

使用参考

启动 Demo

启动快速入门里的arthas-demo。

trace函数

  1. $ trace demo.MathGame run
  2. Press Ctrl+C to abort.
  3. Affect(class-cnt:1 , method-cnt:1) cost in 42 ms.
  4. `---ts=2018-12-04 00:44:17;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
  5.     `---[10.611029ms] demo.MathGame:run()
  6.         +---[0.05638ms] java.util.Random:nextInt()
  7.         +---[10.036885ms] demo.MathGame:primeFactors()
  8.         `---[0.170316ms] demo.MathGame:print()

过滤掉jdk的函数

  1. $ trace -j  demo.MathGame run
  2. Press Ctrl+C to abort.
  3. Affect(class-cnt:1 , method-cnt:1) cost in 31 ms.
  4. `---ts=2018-12-04 01:09:14;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
  5.     `---[5.190646ms] demo.MathGame:run()
  6.         +---[4.465779ms] demo.MathGame:primeFactors()
  7.         `---[0.375324ms] demo.MathGame:print()
  • -j: jdkMethodSkip, skip jdk method trace

据调用耗时过滤

  1. $ trace demo.MathGame run '#cost > 10'
  2. Press Ctrl+C to abort.
  3. Affect(class-cnt:1 , method-cnt:1) cost in 41 ms.
  4. `---ts=2018-12-04 01:12:02;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
  5.     `---[12.033735ms] demo.MathGame:run()
  6.         +---[0.006783ms] java.util.Random:nextInt()
  7.         +---[11.852594ms] demo.MathGame:primeFactors()
  8.         `---[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,count；throws Exception 表明该方法调用中存在异常返回
  • 这里存在一个统计不准确的问题，就是所有方法耗时加起来可能会小于该监测方法的总耗时，这个是由于 Arthas 本身的逻辑会有一定的耗时

trace多个类或者多个函数

trace命令只会trace匹配到的函数里的子调用，并不会向下trace多层。因为trace是代价比较贵的，多层trace可能会导致最终要trace的类和函数非常多。

可以用正则表匹配路径上的多个类和函数，一定程度上达到多层trace的效果。

  1. trace -E com.test.ClassA|org.test.ClassB method1|method2|method3