From 3fbbd9c1fd14b17e4d80552fd60a82d0ca632c7e Mon Sep 17 00:00:00 2001 From: hengyunabc Date: Tue, 4 Dec 2018 01:25:12 +0800 Subject: [PATCH] update trace doc --- .../core/command/monitor200/TraceCommand.java | 2 +- site/src/site/sphinx/en/trace.md | 104 +++++++----------- site/src/site/sphinx/trace.md | 99 +++++++---------- 3 files changed, 79 insertions(+), 126 deletions(-) diff --git a/core/src/main/java/com/taobao/arthas/core/command/monitor200/TraceCommand.java b/core/src/main/java/com/taobao/arthas/core/command/monitor200/TraceCommand.java index e12561305..ce5861896 100644 --- a/core/src/main/java/com/taobao/arthas/core/command/monitor200/TraceCommand.java +++ b/core/src/main/java/com/taobao/arthas/core/command/monitor200/TraceCommand.java @@ -28,11 +28,11 @@ import java.util.List; @Name("trace") @Summary("Trace the execution time of specified method invocation.") @Description(value = Constants.EXPRESS_DESCRIPTION + Constants.EXAMPLE + - " trace -E org\\\\.apache\\\\.commons\\\\.lang\\\\.StringUtils isBlank\n" + " trace org.apache.commons.lang.StringUtils isBlank\n" + " trace *StringUtils isBlank\n" + " trace *StringUtils isBlank params[0].length==1\n" + " trace *StringUtils isBlank '#cost>100'\n" + + " trace -E org\\\\.apache\\\\.commons\\\\.lang\\\\.StringUtils isBlank\n" + Constants.WIKI + Constants.WIKI_HOME + "trace") public class TraceCommand extends EnhancerCommand { diff --git a/site/src/site/sphinx/en/trace.md b/site/src/site/sphinx/en/trace.md index 83ff594c0..05a112921 100644 --- a/site/src/site/sphinx/en/trace.md +++ b/site/src/site/sphinx/en/trace.md @@ -24,11 +24,10 @@ 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. +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. -> Notes: -> 1. `watch`/`stack`/`trace`, these three commands all support `$cost`. -> 2. On version `3.0`, pls. use `#cost` instead of `$cost`. + +> `watch`/`stack`/`trace`, these three commands all support `#cost`. ### Notice @@ -36,77 +35,54 @@ Many times what we are interested is the exact trace result when the method call ### Usage -Sample code: +#### Start Demo -```java - public static void main(String[] args) { - List list = new ArrayList(); - list.add("a"); - list.add("b"); +Start `arthas-demo` in [Quick Start](quick-start.md). - List list2 = new ArrayList(); - list2.add("c"); - list2.add("d"); +#### trace method - int len = add(list, list2); - } - - private static int add(List list, List list2) { - int i = 10; - while (i >= 0) { - try { - hehe(i); - } catch (Throwable t) { - t.printStackTrace(); - } - i--; - } - - list.addAll(list2); - return list.size(); - } - - private static void hehe(int i) { - if (i == 0) { - throw new RuntimeException("ZERO"); - } - } -``` - -Trace down method `add`: - -```shell -$ trace com.alibaba.sample.petstore.web.store.module.screen.ItemList add params.length==2 +```bash +$ trace demo.MathGame run Press Ctrl+C to abort. -Affect(class-cnt:1 , method-cnt:1) cost in 144 ms. -`---Tracing... - `---[2ms]com.alibaba.sample.petstore.web.store.module.screen.ItemList:add() - +---[0,0,0ms,11]com.alibaba.sample.petstore.web.store.module.screen.ItemList:hehe() [throws Exception] - +---[1ms]java.lang.Throwable:printStackTrace() - +---[0ms]java.util.List:addAll() - `---[0ms]java.util.List:size() +Affect(class-cnt:1 , method-cnt:1) cost in 42 ms. +`---ts=2018-12-04 00:44:17;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69 + `---[10.611029ms] demo.MathGame:run() + +---[0.05638ms] java.util.Random:nextInt() + +---[10.036885ms] demo.MathGame:primeFactors() + `---[0.170316ms] demo.MathGame:print() ``` -Filter by time cost: +#### Ignore jdk method -```shell -$ trace com.alibaba.sample.petstore.web.store.module.screen.ItemList execute #cost>4 +```bash +$ trace -j demo.MathGame run Press Ctrl+C to abort. -Affect(class-cnt:1 , method-cnt:1) cost in 159 ms. -trace com.alibaba.sample.petstore.web.store.module.screen.ItemList execute #cost>4 -`---thread_name=http-nio-8080-exec-5;id=2c;is_daemon=true;priority=5;TCCL=com.taobao.pandora.boot.embedded.tomcat.TomcatEmbeddedWebappClassLoader - `---[8.866586ms] com.alibaba.sample.petstore.web.store.module.screen.ItemList:execute() - +---[2.847106ms] com.alibaba.sample.petstore.biz.StoreManager:getAllProductItems() - +---[0.765544ms] com.alibaba.sample.petstore.dal.dao.ProductDao:getProductById() - +---[0.021204ms] com.alibaba.sample.petstore.dal.dataobject.Product:getCategoryId() - +---[1.341532ms] com.alibaba.sample.petstore.dal.dao.CategoryDao:getCategoryById() - `---[min=0.005428ms,max=0.094064ms,total=0.105228ms,count=3] com.alibaba.citrus.turbine.Context:put() +Affect(class-cnt:1 , method-cnt:1) cost in 31 ms. +`---ts=2018-12-04 01:09:14;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69 + `---[5.190646ms] demo.MathGame:run() + +---[4.465779ms] demo.MathGame:primeFactors() + `---[0.375324ms] demo.MathGame:print() ``` -> Only the call path which's time cost is higher than `4ms` will be shown. This feature is handy to focus on what's needed to focus when troubleshoot. +* `-j`: jdkMethodSkip, skip jdk method trace + +#### Filtering by cost + +```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. -* "[2.847106ms] com.alibaba.sample.petstore.biz.StoreManager:getAllProductItems()" means "getAllProductItem()" method from "com.alibaba.sample.petstore.biz.StoreManager" takes `2.847106` ms. -* "[min=0.005428ms,max=0.094064ms,total=0.105228ms,count=3] com.alibaba.citrus.turbine.Context:put()" 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 "com.alibaba.citrus.turbine.Context:put()" is `0.105228ms`. If "throws Exception" appears in this line, it means some exceptions have been thrown from this method calls. +* "[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. diff --git a/site/src/site/sphinx/trace.md b/site/src/site/sphinx/trace.md index 7d9b88e95..05ce41a5a 100644 --- a/site/src/site/sphinx/trace.md +++ b/site/src/site/sphinx/trace.md @@ -26,11 +26,9 @@ trace * 特殊用法请参考：[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的结果。 +很多时候我们只想看到某个方法的rt大于某个时间之后的trace结果，现在Arthas可以按照方法执行的耗时来进行过滤了，例如`trace *StringUtils isBlank '#cost>100'`表示当执行时间超过100ms的时候，才会输出trace的结果。 -> 注意： -> 1. watch/stack/trace这个三个命令都支持$cost -> 2. 如果是Arthas 3.0，请把`$cost`改为`#cost` +> watch/stack/trace这个三个命令都支持`#cost` ### 注意事项 @@ -38,75 +36,54 @@ trace ### 使用参考 -代码示例： -```java - public static void main(String[] args) { - List list = new ArrayList(); - list.add("a"); - list.add("b"); +#### 启动 Demo - List list2 = new ArrayList(); - list2.add("c"); - list2.add("d"); +启动[快速入门](quick-start.md)里的`arthas-demo`。 - int len = add(list, list2); - } +#### trace函数 - private static int add(List list, List list2) { - int i = 10; - while (i >= 0) { - try { - hehe(i); - } catch (Throwable t) { - t.printStackTrace(); - } - i--; - } - - list.addAll(list2); - return list.size(); - } - - private static void hehe(int i) { - if (i == 0) { - throw new RuntimeException("ZERO"); - } - } -``` - -监测 `add` 方法： - -```shell -$ trace com.alibaba.sample.petstore.web.store.module.screen.ItemList add params.length==2 +```bash +$ trace demo.MathGame run Press Ctrl+C to abort. -Affect(class-cnt:1 , method-cnt:1) cost in 144 ms. -`---Tracing... - `---[2ms]com.alibaba.sample.petstore.web.store.module.screen.ItemList:add() - +---[0,0,0ms,11]com.alibaba.sample.petstore.web.store.module.screen.ItemList:hehe() [throws Exception] - +---[1ms]java.lang.Throwable:printStackTrace() - +---[0ms]java.util.List:addAll() - `---[0ms]java.util.List:size() +Affect(class-cnt:1 , method-cnt:1) cost in 42 ms. +`---ts=2018-12-04 00:44:17;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69 + `---[10.611029ms] demo.MathGame:run() + +---[0.05638ms] java.util.Random:nextInt() + +---[10.036885ms] demo.MathGame:primeFactors() + `---[0.170316ms] demo.MathGame:print() ``` -按照耗时过滤： +#### 过滤掉jdk的函数 -```shell -$ trace com.alibaba.sample.petstore.web.store.module.screen.ItemList execute #cost>4 +```bash +$ trace -j demo.MathGame run Press Ctrl+C to abort. -Affect(class-cnt:1 , method-cnt:1) cost in 159 ms. -trace com.alibaba.sample.petstore.web.store.module.screen.ItemList execute #cost>4 -`---thread_name=http-nio-8080-exec-5;id=2c;is_daemon=true;priority=5;TCCL=com.taobao.pandora.boot.embedded.tomcat.TomcatEmbeddedWebappClassLoader - `---[8.866586ms] com.alibaba.sample.petstore.web.store.module.screen.ItemList:execute() - +---[2.847106ms] com.alibaba.sample.petstore.biz.StoreManager:getAllProductItems() - +---[0.765544ms] com.alibaba.sample.petstore.dal.dao.ProductDao:getProductById() - +---[0.021204ms] com.alibaba.sample.petstore.dal.dataobject.Product:getCategoryId() - +---[1.341532ms] com.alibaba.sample.petstore.dal.dao.CategoryDao:getCategoryById() - `---[min=0.005428ms,max=0.094064ms,total=0.105228ms,count=3] com.alibaba.citrus.turbine.Context:put() +Affect(class-cnt:1 , method-cnt:1) cost in 31 ms. +`---ts=2018-12-04 01:09:14;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69 + `---[5.190646ms] demo.MathGame:run() + +---[4.465779ms] demo.MathGame:primeFactors() + `---[0.375324ms] demo.MathGame:print() ``` + +* `-j`: jdkMethodSkip, skip jdk method trace + +#### 据调用耗时过滤 + +```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() +``` + > 只会展示耗时大于4ms的调用路径，有助于在排查问题的时候，只关注异常情况 - 是不是很眼熟，没错，在 JProfiler 等收费软件中你曾经见识类似的功能，这里你将可以通过命令就能打印出指定调用路径。 友情提醒下，`trace` 在执行的过程中本身是会有一定的性能开销，在统计的报告中并未像 JProfiler 一样预先减去其自身的统计开销。所以这统计出来有些许的不准，渲染路径上调用的类、方法越多，性能偏差越大。但还是能让你看清一些事情的。 -- [2ms] 的含义，`2` 的含义是：当前节点在当前步骤的耗时，单位为毫秒 +- [12.033735ms] 的含义，`12.033735` 的含义是：当前节点在当前步骤的耗时，单位为毫秒 - [0,0,0ms,11]xxx:yyy() [throws Exception]，对该方法中相同的方法调用进行了合并，`0,0,0ms,11` 表示方法调用耗时，`min,max,total,count`；`throws Exception` 表明该方法调用中存在异常返回 - 这里存在一个统计不准确的问题，就是所有方法耗时加起来可能会小于该监测方法的总耗时，这个是由于 Arthas 本身的逻辑会有一定的耗时 \ No newline at end of file