Arthas-trace命令查看方法性能开销耗时、追踪方法调用路径

快来打我* 2023-10-07 22:00 53阅读 0赞

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

### 参数说明 ###

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

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

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

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

### 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()函数。=

### 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 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,count；throws 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