From afc51833219474f4f08998dafb3769f9142ff6c9 Mon Sep 17 00:00:00 2001 From: hengyunabc Date: Thu, 9 Jul 2020 17:09:04 +0800 Subject: [PATCH] update doc --- site/src/site/sphinx/en/trace.md | 60 +++++++++++++++++++++++++++++--- site/src/site/sphinx/trace.md | 54 ++++++++++++++++++++++++++++ 2 files changed, 110 insertions(+), 4 deletions(-) diff --git a/site/src/site/sphinx/en/trace.md b/site/src/site/sphinx/en/trace.md index cd091099..e50bd541 100644 --- a/site/src/site/sphinx/en/trace.md +++ b/site/src/site/sphinx/en/trace.md @@ -33,13 +33,16 @@ Many times what we are interested is the exact trace result when the method call `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 #### Start Demo Start `arthas-demo` in [Quick Start](quick-start.md). -#### trace method +#### Trace method ```bash $ trace demo.MathGame run @@ -55,7 +58,7 @@ Affect(class-cnt:1 , method-cnt:1) cost in 28 ms. ``` -#### trace times limit +#### 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. @@ -125,7 +128,7 @@ Affect(class-cnt:1 , method-cnt:1) cost in 41 ms. * 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 +#### 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. @@ -133,4 +136,53 @@ You can use the regular expression to match multiple classes and methods on the ```bash Trace -E com.test.ClassA|org.test.ClassB method1|method2|method3 -``` \ No newline at end of file +``` + + +#### Dynamic trace + +> Supported since version 3.3.0. + +Open terminal 1, trace the `run` method, and you can see the printout `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 +``` + +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`. + +```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. \ No newline at end of file diff --git a/site/src/site/sphinx/trace.md b/site/src/site/sphinx/trace.md index 85661f09..2d02e2d3 100644 --- a/site/src/site/sphinx/trace.md +++ b/site/src/site/sphinx/trace.md @@ -34,6 +34,11 @@ trace `trace` 能方便的帮助你定位和发现因 RT 高而导致的性能问题缺陷，但其每次只能跟踪一级方法的调用链路。 +参考：[Trace命令的实现原理](https://github.com/alibaba/arthas/issues/597) + +3.3.0 版本后，可以使用动态Trace功能，不断增加新的匹配类，参考下面的示例。 + + ### 使用参考 @@ -137,3 +142,52 @@ trace命令只会trace匹配到的函数里的子调用，并不会向下trace ```bash trace -E com.test.ClassA|org.test.ClassB method1|method2|method3 ``` + +### 动态trace + +3.3.0 版本后支持。 + + +打开终端1，trace `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`等命令也支持类似的功能。