@ -25,85 +25,49 @@ Pls. refer to [core parameters in expression](advice-class.md) for more details.
### Usage
> Notes: if there's quotes character (say, `'`) in the expression, then the whole expression must be wrapped by quotes but with the other type (in this case, `"`) too. On contrary, it's no need to quote the expression itself if there's no quotes character found in it, but it is strongly recommended.
#### Start Demo
Print out calling stack when the first method parameter is "K9-BD-01" for 'getProductById()' method:
Start `arthas-demo` in [Quick Start](quick-start.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:
```java
public static void main(String[] args) {
List<String> list = new ArrayList<String>();
list.add("a");
list.add("b");
List<String> list2 = new ArrayList<String>();
list2.add("c");
list2.add("d");
int len = add(list, list2);
}
private static int add(List<String> list, List<String> 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");
}
}
#### Start Demo
Start `arthas-demo` in [Quick Start](quick-start.md).
> 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.
> 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.
record the calling context of the method `demo.MathGame primeFactors`
- `-n 3`
* `-n 3`
limit the number of the records (avoid overflow for too many records; with `-n` option, Arthas can automatically stop recording once the records reach the specified limit)
#### Property
* Property
|Name|Specification|
|---|---|
@ -52,7 +54,7 @@ Let's record the whole calling contexts:
|CLASS|class name of the object invoking the method|
|METHOD|method being invoked|
#### Condition expression
* Condition expression
Tips:
1. `tt -t *Test print params[0].length==1` with different amounts of parameters;
THROW-EXCEPTION java.lang.IllegalArgumentException: number is: -564322413, need >= 2
at demo.MathGame.primeFactors(MathGame.java:46)
at demo.MathGame.run(MathGame.java:24)
at demo.MathGame.main(MathGame.java:16)
Affect(row-cnt:1) cost in 11 ms.
```
### Re-produce
Since Arthas stores the context of the call, you can even *replay* the method calling afterwards with extra option `-p` to re-produce the issue for advanced troubleshooting.
Since Arthas stores the context of the call, you can even *replay* the method calling afterwards with extra option `-p` to replay the issue for advanced troubleshooting.
```bash
$ tt -i 1004 -p
RE-INDEX 1004
GMT-REPLAY 2018-12-04 11:26:00
OBJECT 0x4b67cf4d
CLASS demo.MathGame
METHOD primeFactors
PARAMETERS[0] @Integer[946738738]
IS-RETURN true
IS-EXCEPTION false
RETURN-OBJ @ArrayList[
@Integer[2],
@Integer[11],
@Integer[17],
@Integer[2531387],
]
Time fragment[1004] successfully replayed.
Affect(row-cnt:1) cost in 14 ms.
```
F.Y.I
1. the calling stack is little different using Arthas now unlike the original;
2. **Loss** of the thread local variables will be a undeniable fact since there is no way for Arthas to record the thread local info (*If you find one, please share with us in [issues tracker](https://github.com/alibaba/arthas/issues)*).
3. **Potential** modifications of objects can happen since only a reference will be recorded while later operations might modify objects without Arthas's watch.
1. **Loss** of the `ThreadLocal`
Arthas save params into an array, then invoke the method with the params again. The method execute in another thead, so the `ThreadLocal` **lost**.
1. params may be modified
Arthas save params into an array, they are object references. The Objects may be modified by other code.
<liclass="toctree-l2"><aclass="reference internal"href="#check-the-dashboard">3. Check the Dashboard</a></li>
<liclass="toctree-l2"><aclass="reference internal"href="#get-the-main-class-of-the-process-with-the-thread-command">4. Get the Main Class of the process with the thread command</a></li>
<liclass="toctree-l2"><aclass="reference internal"href="#get-the-main-class-of-the-arthas-demo-process-with-the-thread-command">4. Get the Main Class of the<codeclass="docutils literal notranslate"><spanclass="pre">arthas-demo</span></code> process with the thread command</a></li>
<liclass="toctree-l2"><aclass="reference internal"href="#decompile-main-class-with-jad-command">5. Decompile Main Class with jad command</a></li>
<spanid="get-the-main-class-of-the-process-with-the-thread-command"></span><h2>4. Get the Main Class of the process with the thread command<aclass="headerlink"href="#get-the-main-class-of-the-process-with-the-thread-command" title="Permalink to this headline">¶</a></h2>
<spanid="get-the-main-class-of-the-arthas-demo-process-with-the-thread-command"></span><h2>4. Get the Main Class of the <codeclass="docutils literal notranslate"><spanclass="pre">arthas-demo</span></code>process with the thread command<aclass="headerlink"href="#get-the-main-class-of-the-arthas-demo-process-with-the-thread-command" title="Permalink to this headline">¶</a></h2>
<spanid="usage"></span><h2>Usage<aclass="headerlink"href="#usage"title="Permalink to this headline">¶</a></h2>
<blockquote>
<div>Notes: if there’s quotes character (say, <codeclass="docutils literal notranslate"><spanclass="pre">'</span></code>) in the expression, then the whole expression must be wrapped by quotes but with the other type (in this case, <codeclass="docutils literal notranslate"><spanclass="pre">"</span></code>) too. On contrary, it’s no need to quote the expression itself if there’s no quotes character found in it, but it is strongly recommended.</div></blockquote>
<p>Print out calling stack when the first method parameter is “K9-BD-01” for ‘getProductById()’ method:</p>
<spanid="filtering-by-condition-expression"></span><h3>Filtering by condition expression<aclass="headerlink"href="#filtering-by-condition-expression"title="Permalink to this headline">¶</a></h3>
at com.alibaba.sample.petstore.web.store.module.screen.ItemList.execute<spanclass="o">(</span>ItemList.java:50<spanclass="o">)</span>
at com.alibaba.sample.petstore.web.store.module.screen.ItemList<spanclass="nv">$$</span>FastClassByCGLIB<spanclass="nv">$$</span>40b2f45f.invoke<spanclass="o">(</span><generated>:-1<spanclass="o">)</span>
at net.sf.cglib.reflect.FastMethod.invoke<spanclass="o">(</span>FastMethod.java:53<spanclass="o">)</span>
at com.alibaba.citrus.service.moduleloader.impl.adapter.MethodInvoker.invoke<spanclass="o">(</span>MethodInvoker.java:70<spanclass="o">)</span>
at com.alibaba.citrus.service.moduleloader.impl.adapter.DataBindingAdapter.executeAndReturn<spanclass="o">(</span>DataBindingAdapter.java:41<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.PerformScreenValve.performScreenModule<spanclass="o">(</span>PerformScreenValve.java:111<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.PerformScreenValve.invoke<spanclass="o">(</span>PerformScreenValve.java:74<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.PerformActionValve.invoke<spanclass="o">(</span>PerformActionValve.java:73<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invoke<spanclass="o">(</span>PipelineImpl.java:210<spanclass="o">)</span>
at com.alibaba.sample.petstore.web.store.module.screen.ItemList.execute<spanclass="o">(</span>ItemList.java:50<spanclass="o">)</span>
at com.alibaba.sample.petstore.web.store.module.screen.ItemList<spanclass="nv">$$</span>FastClassByCGLIB<spanclass="nv">$$</span>40b2f45f.invoke<spanclass="o">(</span><generated>:-1<spanclass="o">)</span>
at net.sf.cglib.reflect.FastMethod.invoke<spanclass="o">(</span>FastMethod.java:53<spanclass="o">)</span>
at com.alibaba.citrus.service.moduleloader.impl.adapter.MethodInvoker.invoke<spanclass="o">(</span>MethodInvoker.java:70<spanclass="o">)</span>
at com.alibaba.citrus.service.moduleloader.impl.adapter.DataBindingAdapter.executeAndReturn<spanclass="o">(</span>DataBindingAdapter.java:41<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.PerformScreenValve.performScreenModule<spanclass="o">(</span>PerformScreenValve.java:111<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.PerformScreenValve.invoke<spanclass="o">(</span>PerformScreenValve.java:74<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.PerformActionValve.invoke<spanclass="o">(</span>PerformActionValve.java:73<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invoke<spanclass="o">(</span>PipelineImpl.java:210<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.valve.ChooseValve.invoke<spanclass="o">(</span>ChooseValve.java:98<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
...
Affect<spanclass="o">(</span>class-cnt:1 , method-cnt:1<spanclass="o">)</span> cost in <spanclass="m">30</span> ms.
at demo.MathGame.main<spanclass="o">(</span>MathGame.java:16<spanclass="o">)</span>
Command execution <spanclass="nb">times</span> exceed limit: <spanclass="m">2</span>, so <spanclass="nb">command</span> will exit. You can <spanclass="nb">set</span> it with -n option.
</pre></div>
</div>
<p>Print out the calling stack when method ‘execute()’ takes more than 30ms to finish:</p>
at com.alibaba.sample.petstore.web.store.module.screen.ItemList<spanclass="nv">$$</span>FastClassByCGLIB<spanclass="nv">$$</span>40b2f45f.invoke<spanclass="o">(</span><generated>:-1<spanclass="o">)</span>
at net.sf.cglib.reflect.FastMethod.invoke<spanclass="o">(</span>FastMethod.java:53<spanclass="o">)</span>
at com.alibaba.citrus.service.moduleloader.impl.adapter.MethodInvoker.invoke<spanclass="o">(</span>MethodInvoker.java:70<spanclass="o">)</span>
at com.alibaba.citrus.service.moduleloader.impl.adapter.DataBindingAdapter.executeAndReturn<spanclass="o">(</span>DataBindingAdapter.java:41<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.PerformScreenValve.performScreenModule<spanclass="o">(</span>PerformScreenValve.java:111<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.PerformScreenValve.invoke<spanclass="o">(</span>PerformScreenValve.java:74<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.PerformActionValve.invoke<spanclass="o">(</span>PerformActionValve.java:73<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invoke<spanclass="o">(</span>PipelineImpl.java:210<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.valve.ChooseValve.invoke<spanclass="o">(</span>ChooseValve.java:98<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invoke<spanclass="o">(</span>PipelineImpl.java:210<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.valve.LoopValve.invokeBody<spanclass="o">(</span>LoopValve.java:105<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.valve.LoopValve.invoke<spanclass="o">(</span>LoopValve.java:83<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.PageAuthorizationValve.invoke<spanclass="o">(</span>PageAuthorizationValve.java:105<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.CheckCsrfTokenValve.invoke<spanclass="o">(</span>CheckCsrfTokenValve.java:123<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.AnalyzeURLValve.invoke<spanclass="o">(</span>AnalyzeURLValve.java:126<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.SetLoggingContextValve.invoke<spanclass="o">(</span>SetLoggingContextValve.java:66<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.turbine.pipeline.valve.PrepareForTurbineValve.invoke<spanclass="o">(</span>PrepareForTurbineValve.java:52<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invokeNext<spanclass="o">(</span>PipelineImpl.java:157<spanclass="o">)</span>
at com.alibaba.citrus.service.pipeline.impl.PipelineImpl<spanclass="nv">$PipelineContextImpl</span>.invoke<spanclass="o">(</span>PipelineImpl.java:210<spanclass="o">)</span>
at com.alibaba.citrus.webx.impl.WebxControllerImpl.service<spanclass="o">(</span>WebxControllerImpl.java:43<spanclass="o">)</span>
at com.alibaba.citrus.webx.impl.WebxRootControllerImpl.handleRequest<spanclass="o">(</span>WebxRootControllerImpl.java:53<spanclass="o">)</span>
at com.alibaba.citrus.webx.support.AbstractWebxRootController.service<spanclass="o">(</span>AbstractWebxRootController.java:165<spanclass="o">)</span>
...
Affect<spanclass="o">(</span>class-cnt:1 , method-cnt:1<spanclass="o">)</span> cost in <spanclass="m">35</span> ms.
<li>Pls. also refer to <aclass="reference external"href="https://github.com/alibaba/arthas/issues/71">https://github.com/alibaba/arthas/issues/71</a> for more advanced usage</li>
<li>OGNL official site: <aclass="reference external"href="https://commons.apache.org/proper/commons-ognl/language-guide.html">https://commons.apache.org/proper/commons-ognl/language-guide.html</a></li>
</ul>
<p>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: <codeclass="docutils literal notranslate"><spanclass="pre">trace</span><spanclass="pre">*StringUtils</span><spanclass="pre">isBlank</span><spanclass="pre">'$cost>100'</span></code> means trace result will only be output when the executing time exceeds 100ms.</p>
<p>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: <codeclass="docutils literal notranslate"><spanclass="pre">trace</span><spanclass="pre">*StringUtils</span><spanclass="pre">isBlank</span><spanclass="pre">'#cost>100'</span></code> means trace result will only be output when the executing time exceeds 100ms.</p>
<blockquote>
<div><p>Notes:</p>
<olclass="simple">
<li><codeclass="docutils literal notranslate"><spanclass="pre">watch</span></code>/<codeclass="docutils literal notranslate"><spanclass="pre">stack</span></code>/<codeclass="docutils literal notranslate"><spanclass="pre">trace</span></code>, these three commands all support <codeclass="docutils literal notranslate"><spanclass="pre">$cost</span></code>.</li>
<li>On version <codeclass="docutils literal notranslate"><spanclass="pre">3.0</span></code>, pls. use <codeclass="docutils literal notranslate"><spanclass="pre">#cost</span></code> instead of <codeclass="docutils literal notranslate"><spanclass="pre">$cost</span></code>.</li>
</ol>
</div></blockquote>
<div><codeclass="docutils literal notranslate"><spanclass="pre">watch</span></code>/<codeclass="docutils literal notranslate"><spanclass="pre">stack</span></code>/<codeclass="docutils literal notranslate"><spanclass="pre">trace</span></code>, these three commands all support <codeclass="docutils literal notranslate"><spanclass="pre">#cost</span></code>.</div></blockquote>
</div>
<divclass="section"id="notice">
<spanid="notice"></span><h2>Notice<aclass="headerlink"href="#notice"title="Permalink to this headline">¶</a></h2>
@ -255,76 +256,60 @@
</div>
<divclass="section"id="usage">
<spanid="usage"></span><h2>Usage<aclass="headerlink"href="#usage"title="Permalink to this headline">¶</a></h2>
<div>Only the call path which’s time cost is higher than <codeclass="docutils literal notranslate"><spanclass="pre">4ms</span></code> will be shown. This feature is handy to focus on what’s needed to focus when troubleshoot.</div></blockquote>
<div>Only the call path which’s time cost is higher than <codeclass="docutils literal notranslate"><spanclass="pre">10ms</span></code> will be shown. This feature is handy to focus on what’s needed to focus when troubleshoot.</div></blockquote>
<ulclass="simple">
<li>Here Arthas provides the similar functionality JProfile and other commercial software provide. Compared to these professional softwares, Arthas doesn’t deduce the time cost <codeclass="docutils literal notranslate"><spanclass="pre">trace</span></code> itself takes, therefore it is not as accurate as these softwares offer. More classes and methods on the calling path, more inaccurate <codeclass="docutils literal notranslate"><spanclass="pre">trace</span></code> output is, but it is still helpful for diagnostics where the bottleneck is.</li>
<li>“[2.847106ms] com.alibaba.sample.petstore.biz.StoreManager:getAllProductItems()” means “getAllProductItem()” method from “com.alibaba.sample.petstore.biz.StoreManager” takes <codeclass="docutils literal notranslate"><spanclass="pre">2.847106</span></code> ms.</li>
<li>“[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 <codeclass="docutils literal notranslate"><spanclass="pre">0.005428</span></code> ms, the maximum time cost is <codeclass="docutils literal notranslate"><spanclass="pre">0.094064</span></code> ms, and the total time cost for all method calls (<codeclass="docutils literal notranslate"><spanclass="pre">3</span></code> times in total) to “com.alibaba.citrus.turbine.Context:put()” is <codeclass="docutils literal notranslate"><spanclass="pre">0.105228ms</span></code>. If “throws Exception” appears in this line, it means some exceptions have been thrown from this method calls.</li>
<li>“[12.033735ms]” means the method on the node takes <codeclass="docutils literal notranslate"><spanclass="pre">12.033735</span></code> ms.</li>
<li>“[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 <codeclass="docutils literal notranslate"><spanclass="pre">0.005428</span></code> ms, the maximum time cost is <codeclass="docutils literal notranslate"><spanclass="pre">0.094064</span></code> ms, and the total time cost for all method calls (<codeclass="docutils literal notranslate"><spanclass="pre">3</span></code> times in total) to “demo:call()” is <codeclass="docutils literal notranslate"><spanclass="pre">0.105228ms</span></code>. If “throws Exception” appears in this line, it means some exceptions have been thrown from this method calls.</li>
<li>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.</li>
<p>With the help of <codeclass="docutils literal notranslate"><spanclass="pre">tt</span></code> (<em>TimeTunnel</em>), you can check the contexts of the methods at different times in execution history.</p>
<divclass="section"id="usage">
<spanid="usage"></span><h2>Usage<aclass="headerlink"href="#usage"title="Permalink to this headline">¶</a></h2>
<spanid="start-demo"></span><h3>Start Demo<aclass="headerlink"href="#start-demo"title="Permalink to this headline">¶</a></h3>
<p>Start <codeclass="docutils literal notranslate"><spanclass="pre">arthas-demo</span></code> in <aclass="reference internal"href="quick-start.html"><spanclass="doc">Quick Start</span></a>.</p>
</div>
<divclass="section"id="record-method-calls">
<spanid="record-method-calls"></span><h3>Record method calls<aclass="headerlink"href="#record-method-calls"title="Permalink to this headline">¶</a></h3>
<p>record the calling context of the method <codeclass="docutils literal notranslate"><spanclass="pre">*Test.print</span></code></p>
<p>record the calling context of the method <codeclass="docutils literal notranslate"><spanclass="pre">demo.MathGame</span><spanclass="pre">primeFactors</span></code></p>
<p>limit the number of the records (avoid overflow for too many records; with <codeclass="docutils literal notranslate"><spanclass="pre">-n</span></code> option, Arthas can automatically stop recording once the records reach the specified limit)</p>
</li>
<li><pclass="first">Property</p>
</li>
</ul>
</div>
<divclass="section"id="property">
<spanid="property"></span><h3>Property<aclass="headerlink"href="#property"title="Permalink to this headline">¶</a></h3>
<tableborder="1"class="docutils">
<thead>
<tr>
@ -281,9 +276,9 @@
<td>method being invoked</td>
</tr>
</tbody>
</table></div>
<div class="section"id="condition-expression">
<spanid="condition-expression"></span><h3>Condition expression<aclass="headerlink"href="#condition-expression"title="Permalink to this headline">¶</a></h3>
</table><ulclass="simple">
<li>Condition expression</li>
</ul>
<p>Tips:</p>
<olclass="simple">
<li><codeclass="docutils literal notranslate"><spanclass="pre">tt</span><spanclass="pre">-t</span><spanclass="pre">*Test</span><spanclass="pre">print</span><spanclass="pre">params[0].length==1</span></code> with different amounts of parameters;</li>
@ -299,46 +294,35 @@
</ul>
</div>
</div>
</div>
<divclass="section"id="searching-for-records">
<spanid="searching-for-records"></span><h2>Searching for records<aclass="headerlink"href="#searching-for-records"title="Permalink to this headline">¶</a></h2>
<divclass="section"id="all-the-recorded">
<spanid="all-the-recorded"></span><h3>All the recorded<aclass="headerlink"href="#all-the-recorded"title="Permalink to this headline">¶</a></h3>
<spanid="searching-for-records"></span><h3>Searching for records<aclass="headerlink"href="#searching-for-records"title="Permalink to this headline">¶</a></h3>
<spanid="check-context-of-the-call"></span><h2>Check context of the call<aclass="headerlink"href="#check-context-of-the-call"title="Permalink to this headline">¶</a></h2>
<spanid="check-context-of-the-call"></span><h3>Check context of the call<aclass="headerlink"href="#check-context-of-the-call"title="Permalink to this headline">¶</a></h3>
<p>Using <codeclass="docutils literal notranslate"><spanclass="pre">tt</span><spanclass="pre">-i</span><spanclass="pre"><index></span></code> to check a specific calling details.</p>
THROW-EXCEPTION java.lang.IllegalArgumentException: number is: -564322413, need ><spanclass="o">=</span><spanclass="m">2</span>
at demo.MathGame.primeFactors<spanclass="o">(</span>MathGame.java:46<spanclass="o">)</span>
at demo.MathGame.run<spanclass="o">(</span>MathGame.java:24<spanclass="o">)</span>
at demo.MathGame.main<spanclass="o">(</span>MathGame.java:16<spanclass="o">)</span>
Affect<spanclass="o">(</span>row-cnt:1<spanclass="o">)</span> cost in <spanclass="m">11</span> ms.
</pre></div>
</div>
</div>
<divclass="section"id="re-produce">
<spanid="re-produce"></span><h2>Re-produce<aclass="headerlink"href="#re-produce"title="Permalink to this headline">¶</a></h2>
<p>Since Arthas stores the context of the call, you can even <em>replay</em> the method calling afterwards with extra option <codeclass="docutils literal notranslate"><spanclass="pre">-p</span></code> to re-produce the issue for advanced troubleshooting.</p>
<spanid="replay-record"></span><h2>Replay record<aclass="headerlink"href="#replay-record"title="Permalink to this headline">¶</a></h2>
<p>Since Arthas stores the context of the call, you can even <em>replay</em> the method calling afterwards with extra option <codeclass="docutils literal notranslate"><spanclass="pre">-p</span></code> to replay the issue for advanced troubleshooting.</p>
Time fragment<spanclass="o">[</span><spanclass="m">1004</span><spanclass="o">]</span> successfully replayed.
Affect<spanclass="o">(</span>row-cnt:1<spanclass="o">)</span> cost in <spanclass="m">14</span> ms.
</pre></div>
</div>
<p>F.Y.I</p>
<olclass="simple">
<li>the calling stack is little different using Arthas now unlike the original;</li>
<li><strong>Loss</strong> of the thread local variables will be a undeniable fact since there is no way for Arthas to record the thread local info (<em>If you find one, please share with us in <aclass="reference external"href="https://github.com/alibaba/arthas/issues">issues tracker</a></em>).</li>
<li><strong>Potential</strong> modifications of objects can happen since only a reference will be recorded while later operations might modify objects without Arthas’s watch.</li>
<ol>
<li><pclass="first"><strong>Loss</strong> of the <codeclass="docutils literal notranslate"><spanclass="pre">ThreadLocal</span></code></p>
<p>Arthas save params into an array, then invoke the method with the params again. The method execute in another thead, so the <codeclass="docutils literal notranslate"><spanclass="pre">ThreadLocal</span></code><strong>lost</strong>.</p>
</li>
<li><pclass="first">params may be modified</p>
<p>Arthas save params into an array, they are object references. The Objects may be modified by other code.</p>
<liclass="toctree-l4"><aclass="reference internal"href="#check-the-out-parameters-and-return-value">Check the <codeclass="docutils literal notranslate"><spanclass="pre">out</span><spanclass="pre">parameters</span></code> and <codeclass="docutils literal notranslate"><spanclass="pre">return</span><spanclass="pre">value</span></code></a></li>
<liclass="toctree-l4"><aclass="reference internal"href="#check-before-and-after-at-the-same-time">Check <em>before</em> and <em>after</em> at the same time</a></li>
@ -282,7 +283,10 @@
</div>
<divclass="section"id="usage">
<spanid="usage"></span><h2>Usage<aclass="headerlink"href="#usage"title="Permalink to this headline">¶</a></h2>
<divclass="section"id="start-demo">
<spanid="start-demo"></span><h3>Start Demo<aclass="headerlink"href="#start-demo"title="Permalink to this headline">¶</a></h3>
<p>Start <codeclass="docutils literal notranslate"><spanclass="pre">arthas-demo</span></code> in <aclass="reference internal"href="quick-start.html"><spanclass="doc">Quick Start</span></a>.</p>
<spanid="check-the-out-parameters-and-return-value"></span><h3>Check the <codeclass="docutils literal notranslate"><spanclass="pre">out</span><spanclass="pre">parameters</span></code> and <codeclass="docutils literal notranslate"><spanclass="pre">return</span><spanclass="pre">value</span></code><aclass="headerlink"href="#check-the-out-parameters-and-return-value"title="Permalink to this headline">¶</a></h3>
at demo.MathGame.main<spanclass="o">(</span>MathGame.java:16<spanclass="o">)</span>
Command execution <spanclass="nb">times</span> exceed limit: <spanclass="m">2</span>, so <spanclass="nb">command</span> will exit. You can <spanclass="nb">set</span> it with -n option.
hengyunabc
6 years ago