mirror of
https://gitee.com/arthas/arthas.git
synced 2024-12-03 12:48:48 +08:00
parent
19ed2103bb
commit
70910d452a
@ -1,6 +1,8 @@
|
||||
trace
|
||||
=====
|
||||
|
||||
[`trace` online tutorial](https://alibaba.github.io/arthas/arthas-tutorials?language=en&id=command-trace)
|
||||
|
||||
> Trace method calling path, and output the time cost for each node in the path.
|
||||
|
||||
`trace` can track the calling path specified by `class-pattern` / `method-pattern`, and calculate the time cost on the whole path.
|
||||
|
@ -1,6 +1,8 @@
|
||||
trace
|
||||
===
|
||||
|
||||
[`trace`在线教程](https://alibaba.github.io/arthas/arthas-tutorials?language=cn&id=command-trace)
|
||||
|
||||
> 方法内部调用路径,并输出方法路径上的每个节点上耗时
|
||||
|
||||
`trace` 命令能主动搜索 `class-pattern`/`method-pattern` 对应的方法调用路径,渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
|
||||
|
16
tutorials/katacoda/command-trace-cn/arthas-boot.md
Normal file
16
tutorials/katacoda/command-trace-cn/arthas-boot.md
Normal file
@ -0,0 +1,16 @@
|
||||
|
||||
|
||||
|
||||
|
||||
在新的`Terminal 2`里,下载`arthas-boot.jar`,再用`java -jar`命令启动:
|
||||
|
||||
`wget https://alibaba.github.io/arthas/arthas-boot.jar
|
||||
java -jar arthas-boot.jar`{{execute T2}}
|
||||
|
||||
`arthas-boot`是`Arthas`的启动程序,它启动后,会列出所有的Java进程,用户可以选择需要诊断的目标进程。
|
||||
|
||||
选择第一个进程,输入 `1`{{execute T2}} ,再`Enter/回车`:
|
||||
|
||||
Attach成功之后,会打印Arthas LOGO。输入 `help`{{execute T2}} 可以获取到更多的帮助信息。
|
||||
|
||||
![Arthas Boot](/arthas/scenarios/common-resources/assets/arthas-boot.png)
|
10
tutorials/katacoda/command-trace-cn/arthas-demo.md
Normal file
10
tutorials/katacoda/command-trace-cn/arthas-demo.md
Normal file
@ -0,0 +1,10 @@
|
||||
|
||||
|
||||
|
||||
|
||||
下载`arthas-demo.jar`,再用`java -jar`命令启动:
|
||||
|
||||
`wget https://alibaba.github.io/arthas/arthas-demo.jar
|
||||
java -jar arthas-demo.jar`{{execute T1}}
|
||||
|
||||
`arthas-demo`是一个很简单的程序,它随机生成整数,再执行因式分解,把结果打印出来。如果生成的随机数是负数,则会打印提示信息。
|
12
tutorials/katacoda/command-trace-cn/finish.md
Normal file
12
tutorials/katacoda/command-trace-cn/finish.md
Normal file
@ -0,0 +1,12 @@
|
||||
|
||||
在“mbean”中,我们演示了了Arthas的mbean命令。如果有更多的技巧或者使用疑问,欢迎在Issue里提出。
|
||||
|
||||
* Issues: https://github.com/alibaba/arthas/issues
|
||||
* 文档: https://alibaba.github.io/arthas
|
||||
|
||||
|
||||
如果您在使用Arthas,请让我们知道,您的使用对我们非常重要:[查看](https://github.com/alibaba/arthas/issues/111)
|
||||
|
||||
欢迎关注公众号,获取Arthas项目的信息,源码分析,案例实践。
|
||||
|
||||
![Arthas公众号](/arthas/scenarios/common-resources/assets/qrcode_gongzhonghao.jpg)
|
35
tutorials/katacoda/command-trace-cn/index.json
Normal file
35
tutorials/katacoda/command-trace-cn/index.json
Normal file
@ -0,0 +1,35 @@
|
||||
{
|
||||
"title": "Arthas mbean命令",
|
||||
"description": "Arthas mbean命令",
|
||||
"difficulty": "精通者",
|
||||
"time": "10-20 分钟",
|
||||
"details": {
|
||||
"steps": [
|
||||
{
|
||||
"title": "启动arthas demo",
|
||||
"text": "arthas-demo.md"
|
||||
},
|
||||
{
|
||||
"title": "启动arthas-boot",
|
||||
"text": "arthas-boot.md"
|
||||
},
|
||||
{
|
||||
"title": "mbean命令",
|
||||
"text": "mbean.md"
|
||||
}
|
||||
],
|
||||
"intro": {
|
||||
"text": "intro.md"
|
||||
},
|
||||
"finish": {
|
||||
"text": "finish.md"
|
||||
}
|
||||
},
|
||||
"environment": {
|
||||
"uilayout": "terminal"
|
||||
},
|
||||
"backend": {
|
||||
"imageid": "java",
|
||||
"environmentsprotocol": "http"
|
||||
}
|
||||
}
|
23
tutorials/katacoda/command-trace-cn/intro.md
Normal file
23
tutorials/katacoda/command-trace-cn/intro.md
Normal file
@ -0,0 +1,23 @@
|
||||
|
||||
|
||||
|
||||
![Arthas](https://alibaba.github.io/arthas/_images/arthas.png)
|
||||
|
||||
`Arthas` 是Alibaba开源的Java诊断工具,深受开发者喜爱。在线排查问题,无需重启;动态跟踪Java代码;实时监控JVM状态。
|
||||
|
||||
`Arthas` 支持JDK 6+,支持Linux/Mac/Windows,采用命令行交互模式,同时提供丰富的 `Tab` 自动补全功能,进一步方便进行问题的定位和诊断。
|
||||
|
||||
当你遇到以下类似问题而束手无策时,Arthas可以帮助你解决:
|
||||
|
||||
- 这个类从哪个 jar 包加载的?为什么会报各种类相关的 Exception?
|
||||
- 我改的代码为什么没有执行到?难道是我没 commit?分支搞错了?
|
||||
- 遇到问题无法在线上 debug,难道只能通过加日志再重新发布吗?
|
||||
- 线上遇到某个用户的数据处理有问题,但线上同样无法 debug,线下无法重现!
|
||||
- 是否有一个全局视角来查看系统的运行状况?
|
||||
- 有什么办法可以监控到JVM的实时运行状态?
|
||||
- 怎么快速定位应用的热点,生成火焰图?
|
||||
|
||||
本教程会以一个简单的应用为例,演示mbean命令。
|
||||
|
||||
* Github: https://github.com/alibaba/arthas
|
||||
* 文档: https://alibaba.github.io/arthas/
|
198
tutorials/katacoda/command-trace-cn/trace.md
Normal file
198
tutorials/katacoda/command-trace-cn/trace.md
Normal file
@ -0,0 +1,198 @@
|
||||
|
||||
> 方法内部调用路径,并输出方法路径上的每个节点上耗时
|
||||
|
||||
`trace` 命令能主动搜索 `class-pattern`/`method-pattern` 对应的方法调用路径,渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
|
||||
|
||||
### 参数说明
|
||||
|
||||
|参数名称|参数说明|
|
||||
|---:|:---|
|
||||
|*class-pattern*|类名表达式匹配|
|
||||
|*method-pattern*|方法名表达式匹配|
|
||||
|*condition-express*|条件表达式|
|
||||
|[E]|开启正则表达式匹配,默认为通配符匹配|
|
||||
|`[n:]`|命令执行次数|
|
||||
|`#cost`|方法执行耗时|
|
||||
|
||||
这里重点要说明的是观察表达式,观察表达式的构成主要由 ognl 表达式组成,所以你可以这样写`"{params,returnObj}"`,只要是一个合法的 ognl 表达式,都能被正常支持。
|
||||
|
||||
观察的维度也比较多,主要体现在参数 `advice` 的数据结构上。`Advice` 参数最主要是封装了通知节点的所有信息。
|
||||
|
||||
|
||||
请参考[表达式核心变量](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的结果。
|
||||
|
||||
> watch/stack/trace这个三个命令都支持`#cost`
|
||||
|
||||
### 注意事项
|
||||
|
||||
`trace` 能方便的帮助你定位和发现因 RT 高而导致的性能问题缺陷,但其每次只能跟踪一级方法的调用链路。
|
||||
|
||||
参考:[Trace命令的实现原理](https://github.com/alibaba/arthas/issues/597)
|
||||
|
||||
3.3.0 版本后,可以使用动态Trace功能,不断增加新的匹配类,参考下面的示例。
|
||||
|
||||
|
||||
### 使用参考
|
||||
|
||||
#### trace函数
|
||||
|
||||
`trace demo.MathGame run`{{execute T2}}
|
||||
|
||||
```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]
|
||||
```
|
||||
|
||||
#### trace次数限制
|
||||
|
||||
如果方法调用的次数很多,那么可以用`-n`参数指定捕捉结果的次数。比如下面的例子里,捕捉到一次调用就退出命令。
|
||||
|
||||
`trace demo.MathGame run -n 1`{{execute T2}}
|
||||
|
||||
```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 --skipJDKMethod false demo.MathGame run`{{execute T2}}
|
||||
|
||||
默认情况下,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
|
||||
```
|
||||
|
||||
#### 据调用耗时过滤
|
||||
|
||||
`trace demo.MathGame run '#cost > 10'`{{execute T2}}
|
||||
|
||||
```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()
|
||||
```
|
||||
|
||||
> 只会展示耗时大于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
|
||||
```
|
||||
|
||||
### 动态trace
|
||||
|
||||
3.3.0 版本后支持。
|
||||
|
||||
|
||||
打开终端1,trace `run`函数,可以看到打印出 `listenerId: 1`:
|
||||
|
||||
`trace demo.MathGame run`{{execute T2}}
|
||||
|
||||
```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`。
|
||||
|
||||
`trace demo.MathGame primeFactors --listenerId 1`{{execute T2}}
|
||||
|
||||
```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`等命令也支持类似的功能。
|
16
tutorials/katacoda/command-trace-en/arthas-boot.md
Normal file
16
tutorials/katacoda/command-trace-en/arthas-boot.md
Normal file
@ -0,0 +1,16 @@
|
||||
|
||||
|
||||
|
||||
|
||||
In the new `Terminal 2`, download `arthas-boot.jar` and start with the `java -jar` command:
|
||||
|
||||
`wget https://alibaba.github.io/arthas/arthas-boot.jar
|
||||
java -jar arthas-boot.jar`{{execute T2}}
|
||||
|
||||
`arthas-boot` is the launcher for `Arthas`. It lists all the Java processes, and the user can select the target process to be diagnosed.
|
||||
|
||||
Select the first process, type `1`{{execute T2}} ,then type `Enter`:
|
||||
|
||||
After the Attach is successful, Arthas LOGO is printed. Enter `help`{{execute T2}} for more help.
|
||||
|
||||
![Arthas Boot](/arthas/scenarios/common-resources/assets/arthas-boot.png)
|
11
tutorials/katacoda/command-trace-en/arthas-demo.md
Normal file
11
tutorials/katacoda/command-trace-en/arthas-demo.md
Normal file
@ -0,0 +1,11 @@
|
||||
|
||||
|
||||
|
||||
|
||||
Download `arthas-demo.jar` and start with the `java -jar` command:
|
||||
|
||||
`wget https://alibaba.github.io/arthas/arthas-demo.jar
|
||||
java -jar arthas-demo.jar`{{execute T1}}
|
||||
|
||||
`arthas-demo` is a very simple program that randomly generates integers, performs factorization, and prints the results.
|
||||
If the generated random number is negative, a error message will be printed.
|
8
tutorials/katacoda/command-trace-en/finish.md
Normal file
8
tutorials/katacoda/command-trace-en/finish.md
Normal file
@ -0,0 +1,8 @@
|
||||
|
||||
The `mbean Tutorial` demonstrates the usage of mbean. If you have more tips or questions, please feel free to ask in Issue.
|
||||
|
||||
* Issues: https://github.com/alibaba/arthas/issues
|
||||
* Documentation: https://alibaba.github.io/arthas
|
||||
|
||||
|
||||
If you are using Arthas, please let us know. Your use is very important to us: [View](https://github.com/alibaba/arthas/issues/111)
|
35
tutorials/katacoda/command-trace-en/index.json
Normal file
35
tutorials/katacoda/command-trace-en/index.json
Normal file
@ -0,0 +1,35 @@
|
||||
{
|
||||
"title": "Arthas mbean Command",
|
||||
"description": "Arthas mbean Command",
|
||||
"difficulty": "master",
|
||||
"time": "10-20 minutes",
|
||||
"details": {
|
||||
"steps": [
|
||||
{
|
||||
"title": "Arthas demo",
|
||||
"text": "arthas-demo.md"
|
||||
},
|
||||
{
|
||||
"title": "Start arthas-boot",
|
||||
"text": "arthas-boot.md"
|
||||
},
|
||||
{
|
||||
"title": "mbean Command",
|
||||
"text": "mbean.md"
|
||||
}
|
||||
],
|
||||
"intro": {
|
||||
"text": "intro.md"
|
||||
},
|
||||
"finish": {
|
||||
"text": "finish.md"
|
||||
}
|
||||
},
|
||||
"environment": {
|
||||
"uilayout": "terminal"
|
||||
},
|
||||
"backend": {
|
||||
"imageid": "java",
|
||||
"environmentsprotocol": "http"
|
||||
}
|
||||
}
|
40
tutorials/katacoda/command-trace-en/intro.md
Normal file
40
tutorials/katacoda/command-trace-en/intro.md
Normal file
@ -0,0 +1,40 @@
|
||||
|
||||
|
||||
|
||||
![Arthas](https://alibaba.github.io/arthas/_images/arthas.png)
|
||||
|
||||
`Arthas` is a Java diagnostic tool open-sourced by Alibaba middleware team. Arthas helps developers in trouble-shooting issues in production environment for Java based applications without modifying code or restarting servers.
|
||||
|
||||
`Arthas` supports JDK 6+, supports Linux/Mac/Windows.
|
||||
|
||||
## Background
|
||||
|
||||
Oftentimes the production system network is inaccessible from local development environment. If issues are encountered in production systems, it is impossible to use IDE to debug the application remotely. What’s even worse, debugging in production environment is unacceptable, as it will suspend all the threads, leading to services downtime.
|
||||
|
||||
Developers could always try to reproduce the same issue on the test/staging environment. However, this is tricky as some issues cannot be reproduced easily in a different environment, or even disappear once restarted.
|
||||
|
||||
And if you’re thinking of adding some logs to your code to help trouble-shoot the issue, you will have to go through the following lifecycle: test, staging, and then to production. Time is money! This approach is inefficient! Worse still, the issue may not be fixed since it might be irreproducible once the JVM is restarted, as described above.
|
||||
|
||||
Arthas is built to solve these issues. A developer can troubleshoot production issues on the fly. No JVM restart, no additional code changes. Arthas works as an observer, that is, it will never suspend your running threads.
|
||||
|
||||
## Key features
|
||||
|
||||
- Check whether a class is loaded? Or where the class is loaded from? (Useful for trouble-shooting jar file conflicts)
|
||||
- Decompile a class to ensure the code is running as expected.
|
||||
- Check classloader statistics, e.g. the number of classloaders, the number of classes loaded per classloader, the classloader hierarchy, possible classloader leaks, etc.
|
||||
- Check the method invocation details, e.g. method parameter, returned values, exceptions and etc.
|
||||
- Check the stack trace of specified method invocation. This is useful when a developer wants to know the caller of the method.
|
||||
- Trace the method invocation to find slow sub-invocations.
|
||||
- Monitor method invocation statistics, e.g. QPS (Query Per Second), RT (Return Time), success rate and etc.
|
||||
- Monitor system metrics, thread states and CPU usage, GC statistics and etc.
|
||||
- Supports command line interactive mode, with auto-complete feature enabled.
|
||||
- Supports telnet and WebSocket, which enables both local and remote diagnostics with command line and browsers.
|
||||
- Supports profiler/Flame Graph
|
||||
- Supports JDK 6+
|
||||
- Supports Linux/Mac/Windows
|
||||
|
||||
This tutorial takes a simple application as an example to demonstrate the the usage of mbean.
|
||||
|
||||
* Github: https://github.com/alibaba/arthas
|
||||
* Docs: https://alibaba.github.io/arthas/
|
||||
|
194
tutorials/katacoda/command-trace-en/trace.md
Normal file
194
tutorials/katacoda/command-trace-en/trace.md
Normal file
@ -0,0 +1,194 @@
|
||||
|
||||
> Trace method calling path, and output the time cost for each node in the path.
|
||||
|
||||
`trace` can track the calling path specified by `class-pattern` / `method-pattern`, and calculate the time cost on the whole path.
|
||||
|
||||
### Parameters
|
||||
|
||||
|Name|Specification|
|
||||
|---:|:---|
|
||||
|*class-pattern*|pattern for the class name|
|
||||
|*method-pattern*|pattern for the method name|
|
||||
|*condition-express*|condition expression|
|
||||
|`[E]`|enable regex match, the default behavior is wildcards match|
|
||||
|`[n:]`|execution times|
|
||||
|#cost|time cost|
|
||||
|
||||
There's one thing worthy noting here is observation expression. The observation expression supports OGNL grammar, for example, you can come up a expression like this `"{params,returnObj}"`. All OGNL expressions are supported as long as they are legal to the grammar.
|
||||
|
||||
Thanks for `advice`'s data structure, it is possible to observe from varieties of different angles. Inside `advice` parameter, all necessary information for notification can be found.
|
||||
|
||||
Pls. refer to [core parameters in expression](advice-class.md) for more details.
|
||||
* Pls. also refer to [https://github.com/alibaba/arthas/issues/71](https://github.com/alibaba/arthas/issues/71) for more advanced usage
|
||||
* OGNL official site: [https://commons.apache.org/proper/commons-ognl/language-guide.html](https://commons.apache.org/proper/commons-ognl/language-guide.html)
|
||||
|
||||
Many times what we are interested is the exact trace result when the method call takes time over one particular period. It is possible to achieve this in Arthas, for example: `trace *StringUtils isBlank '#cost>100'` means trace result will only be output when the executing time exceeds 100ms.
|
||||
|
||||
|
||||
> `watch`/`stack`/`trace`, these three commands all support `#cost`.
|
||||
|
||||
### Notice
|
||||
|
||||
`trace` is handy to help discovering and locating the performance flaws in your system, but pls. note Arthas can only trace the first level method call each time.
|
||||
|
||||
|
||||
After version 3.3.0, you can use the Dynamic Trace feature to add new matching classes/methods, see the following example.
|
||||
|
||||
### Usage
|
||||
|
||||
#### Trace method
|
||||
|
||||
`trace demo.MathGame run`{{execute T2}}
|
||||
|
||||
```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]
|
||||
```
|
||||
|
||||
|
||||
#### Trace times limit
|
||||
|
||||
If the method invoked many times, use `-n` options to specify trace times. For example, the command will exit when received a trace result.
|
||||
|
||||
`trace demo.MathGame run -n 1`{{execute T2}}
|
||||
|
||||
```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.
|
||||
```
|
||||
|
||||
#### Include jdk method
|
||||
|
||||
* `--skipJDKMethod <value> ` skip jdk method trace, default value true.
|
||||
|
||||
`trace --skipJDKMethod false demo.MathGame run`{{execute T2}}
|
||||
|
||||
```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
|
||||
```
|
||||
|
||||
#### Filtering by cost
|
||||
|
||||
`trace demo.MathGame run '#cost > 10'`{{execute T2}}
|
||||
|
||||
```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()
|
||||
```
|
||||
|
||||
> Only the call path which's time cost is higher than `10ms` will be shown. This feature is handy to focus on what's needed to focus when troubleshoot.
|
||||
|
||||
* Here Arthas provides the similar functionality JProfile and other commercial software provide. Compared to these professional softwares, Arthas doesn't deduce the time cost `trace` itself takes, therefore it is not as accurate as these softwares offer. More classes and methods on the calling path, more inaccurate `trace` output is, but it is still helpful for diagnostics where the bottleneck is.
|
||||
* "[12.033735ms]" means the method on the node takes `12.033735` ms.
|
||||
* "[min=0.005428ms,max=0.094064ms,total=0.105228ms,count=3] demo:call()" means aggregating all same method calls into one single line. The minimum time cost is `0.005428` ms, the maximum time cost is `0.094064` ms, and the total time cost for all method calls (`3` times in total) to "demo:call()" is `0.105228ms`. If "throws Exception" appears in this line, it means some exceptions have been thrown from this method calls.
|
||||
* The total time cost may not equal to the sum of the time costs each sub method call takes, this is because Arthas instrumented code takes time too.
|
||||
|
||||
|
||||
#### Trace multiple classes or multiple methods
|
||||
|
||||
The trace command will only trace the subcalls in the method to the trace, and will not trace down multiple layers. Because traces are expensive, multi-layer traces can lead to a lot of classes and methods that ultimately have to be traced.
|
||||
|
||||
You can use the regular expression to match multiple classes and methods on the path to achieve a multi-layer trace effect to some extent.
|
||||
|
||||
```bash
|
||||
Trace -E com.test.ClassA|org.test.ClassB method1|method2|method3
|
||||
```
|
||||
|
||||
|
||||
#### Dynamic trace
|
||||
|
||||
> Supported since version 3.3.0.
|
||||
|
||||
Open terminal 1, trace the `run` method, and you can see the printout `listenerId: 1` .
|
||||
|
||||
`trace demo.MathGame run`{{execute T2}}
|
||||
|
||||
```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
|
||||
```
|
||||
|
||||
Now to drill down into the sub method `primeFactors`, you can open a new terminal 2 and use the `telnet localhost 3658` connects to the arthas, then trace `primeFactors` with the specify `listenerId`.
|
||||
|
||||
`trace demo.MathGame primeFactors --listenerId 1`{{execute T2}}
|
||||
|
||||
```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
|
||||
```
|
||||
|
||||
At Terminal 2 prints the results, indicating that a method has been enhanced: `Affect(class count: 1 , method count: 1)`, but no more results are printed.
|
||||
|
||||
At terminal 1, you can see that the trace result has increased by one layer:
|
||||
|
||||
```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
|
||||
```
|
||||
|
||||
Dynamic trace by specifying `listenerId`, you can go deeper and deeper. In addition, commands such as `watch`/`tt`/`monitor` also support similar functionality.
|
Loading…
Reference in New Issue
Block a user