mirror of
https://gitee.com/arthas/arthas.git
synced 2024-12-02 12:17:45 +08:00
279 lines
13 KiB
Markdown
279 lines
13 KiB
Markdown
# trace
|
||
|
||
[`trace`在线教程](https://arthas.aliyun.com/doc/arthas-tutorials.html?language=cn&id=command-trace)
|
||
|
||
::: tip
|
||
方法内部调用路径，并输出方法路径上的每个节点上耗时
|
||
:::
|
||
|
||
`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 表达式，都能被正常支持。
|
||
|
||
请参考[表达式核心变量](advice-class.md)中关于该节点的描述。
|
||
|
||
- 特殊用法请参考：[https://github.com/alibaba/arthas/issues/71](https://github.com/alibaba/arthas/issues/71)
|
||
- OGNL 表达式官网：[https://commons.apache.org/proper/commons-ognl/language-guide.html](https://commons.apache.org/proper/commons-ognl/language-guide.html)
|
||
|
||
很多时候我们只想看到某个方法的 rt 大于某个时间之后的 trace 结果，现在 Arthas 可以按照方法执行的耗时来进行过滤了，例如`trace *StringUtils isBlank '#cost>100'`表示当执行时间超过 100ms 的时候，才会输出 trace 的结果。
|
||
|
||
::: tip
|
||
watch/stack/trace 这个三个命令都支持`#cost`
|
||
:::
|
||
|
||
## 注意事项
|
||
|
||
- `trace` 能方便的帮助你定位和发现因 RT 高而导致的性能问题缺陷，但其每次只能跟踪一级方法的调用链路。
|
||
|
||
参考：[Trace 命令的实现原理](https://github.com/alibaba/arthas/issues/597)
|
||
|
||
- 3.3.0 版本后，可以使用动态 Trace 功能，不断增加新的匹配类，参考下面的示例。
|
||
|
||
- 目前不支持 `trace java.lang.Thread getName`，参考 issue: [#1610](https://github.com/alibaba/arthas/issues/1610) ，考虑到不是非常必要场景，且修复有一定难度，因此当前暂不修复
|
||
|
||
## 使用参考
|
||
|
||
### 启动 Demo
|
||
|
||
启动[快速入门](quick-start.md)里的`math-game`。
|
||
|
||
### trace 函数
|
||
|
||
```bash
|
||
$ 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]
|
||
```
|
||
|
||
::: tip
|
||
结果里的 `#24`，表示在 run 函数里，在源文件的第`24`行调用了`primeFactors()`函数。
|
||
:::
|
||
|
||
### 指定 Class 匹配的最大数量
|
||
|
||
```bash
|
||
$ 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`参数指定捕捉结果的次数。比如下面的例子里，捕捉到一次调用就退出命令。
|
||
|
||
```bash
|
||
$ 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`。
|
||
|
||
```bash
|
||
$ 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
|
||
```
|
||
|
||
### 根据调用耗时过滤
|
||
|
||
```bash
|
||
$ 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()
|
||
```
|
||
|
||
::: tip
|
||
只会展示耗时大于 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 的效果。
|
||
|
||
```bash
|
||
trace -E com.test.ClassA|org.test.ClassB method1|method2|method3
|
||
```
|
||
|
||
### 排除掉指定的类
|
||
|
||
使用 `--exclude-class-pattern` 参数可以排除掉指定的类，比如：
|
||
|
||
```bash
|
||
trace javax.servlet.Filter * --exclude-class-pattern com.demo.TestFilter
|
||
```
|
||
|
||
## 动态 trace
|
||
|
||
::: tip
|
||
3.3.0 版本后支持。
|
||
:::
|
||
|
||
打开终端 1，trace 上面 demo 里的`run`函数，可以看到打印出 `listenerId: 1`：
|
||
|
||
```bash
|
||
[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`。
|
||
|
||
```bash
|
||
[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`函数里的内容：
|
||
|
||
```bash
|
||
`---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)`
|
||
|
||
```bash
|
||
$ 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`参数可以打印出来。
|
||
|
||
```bash
|
||
$ 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 参数打印更多信息
|
||
|
||
::: tip
|
||
watch/trace/monitor/stack/tt 命令都支持 `-v` 参数
|
||
:::
|
||
|
||
当命令执行之后，没有输出结果。有两种可能：
|
||
|
||
1. 匹配到的函数没有被执行
|
||
2. 条件表达式结果是 false
|
||
|
||
但用户区分不出是哪种情况。
|
||
|
||
使用 `-v`选项，则会打印`Condition express`的具体值和执行结果，方便确认。
|