trace命令
使用参考
Arthas 是Alibaba开源的Java诊断工具，深受开发者喜爱。在线排查问题，无需重启；动态跟踪Java代码；实时监控JVM状态。
Arthas 支持JDK 6+，支持Linux/Mac/Windows，采用命令行交互模式，同时提供丰富的 Tab 自动补全功能，进一步方便进行问题的定位和诊断。
当你遇到以下类似问题而束手无策时，Arthas可以帮助你解决：
这个类从哪个 jar 包加载的？为什么会报各种类相关的 Exception？
我改的代码为什么没有执行到？难道是我没 commit？分支搞错了？
遇到问题无法在线上 debug，难道只能通过加日志再重新发布吗？
线上遇到某个用户的数据处理有问题，但线上同样无法 debug，线下无法重现！
是否有一个全局视角来查看系统的运行状况？
有什么办法可以监控到JVM的实时运行状态？
怎么快速定位应用的热点，生成火焰图？
本教程会以一个简单的应用为例，演示trace命令。
Github: https://github.com/alibaba/arthas
文档: https://arthas.aliyun.com/doc/
下载arthas-demo.jar，再用java -jar命令启动：
bash wget https://arthas.aliyun.com/arthas-demo.jar;java -jar arthas-demo.jar
arthas-demo是一个很简单的程序，它随机生成整数，再执行因式分解，把结果打印出来。如果生成的随机数是负数，则会打印提示信息。
在新的Terminal 2里，下载arthas-boot.jar，再用java -jar命令启动：
bash wget https://arthas.aliyun.com/arthas-boot.jar;java -jar arthas-boot.jar
arthas-boot是Arthas的启动程序，它启动后，会列出所有的Java进程，用户可以选择需要诊断的目标进程。
选择第一个进程，输入 1 ，再Enter/回车：
bash 1
Attach成功之后，会打印Arthas LOGO。输入 help 可以获取到更多的帮助信息。
bash help
方法内部调用路径，并输出方法路径上的每个节点上耗时
trace 命令能主动搜索 class-pattern／method-pattern 对应的方法调用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
| 参数名称 | 参数说明 |
| ------------------- | ------------------------------------ |
| class-pattern | 类名表达式匹配 |
| method-pattern | 方法名表达式匹配 |
| condition-express | 条件表达式 |
| [E] | 开启正则表达式匹配，默认为通配符匹配 |
| [n:] | 命令执行次数 |
| #cost | 方法执行耗时 |
这里重点要说明的是观察表达式，观察表达式的构成主要由 ognl 表达式组成，所以你可以这样写"{params,returnObj}"，只要是一个合法的 ognl 表达式，都能被正常支持。
观察的维度也比较多，主要体现在参数 advice 的数据结构上。Advice 参数最主要是封装了通知节点的所有信息。 请参考表达式核心变量中关于该节点的描述。
特殊用法请参考：https://github.com/alibaba/arthas/issues/71
OGNL表达式官网：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命令的实现原理
3.3.0 版本后，可以使用动态Trace功能，不断增加新的匹配类，参考下面的示例。
bash trace demo.MathGame run
按q或者Ctrl+c退出
bash q console $ 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]
如果方法调用的次数很多，那么可以用-n参数指定捕捉结果的次数。比如下面的例子里，捕捉到一次调用就退出命令。
bash trace demo.MathGame run -n 1
按q或者Ctrl+c退出
bash q console $ 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.
--skipJDKMethod <value> skip jdk method trace, default value true.
bash trace --skipJDKMethod false demo.MathGame run
按q或者Ctrl+c退出
bash q
默认情况下，trace不会包含jdk里的函数调用，如果希望trace jdk里的函数，需要显式设置--skipJDKMethod false。
console $ 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'
按q或者Ctrl+c退出
bash q console $ 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的效果。
console trace -E com.test.ClassA|org.test.ClassB method1|method2|method3
3.3.0 版本后支持。 打开终端1，trace run函数，可以看到打印出 listenerId: 1：
bash trace demo.MathGame run
按q或者Ctrl+c退出
bash q console [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 trace demo.MathGame primeFactors --listenerId 1
按q或者Ctrl+c退出
bash q console [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函数里的内容：
console `---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”中，我们演示了了Arthas的trace命令。如果有更多的技巧或者使用疑问，欢迎在Issue里提出。
Issues: https://github.com/alibaba/arthas/issues
文档： https://arthas.aliyun.com/doc
如果您在使用Arthas，请让我们知道。您的使用对我们非常重要：查看
文章拷贝来源：https://start.aliyun.com/course?spm=a2ck6.17690074.0.0.28bc2e7dHTphXs&id=PaiFAkJM
