Arthas trace 命令实战指南Java 方法调用路径耗时追踪与性能瓶颈定位【免费下载链接】arthasAlibaba Java Diagnostic Tool Arthas/Alibaba Java诊断利器Arthas项目地址: https://gitcode.com/gh_mirrors/ar/arthastrace是 Arthas 中用于方法内部调用路径追踪的核心命令它可以跟踪匹配class-pattern/method-pattern的方法在整个调用路径上每一层子调用的耗时并以树形结构输出。本文基于 Arthas 官方文档与 TraceCommand 源码系统讲解 trace 的全部参数、条件表达式、输出结果解读、多层与动态追踪技巧以及耗时误差分析帮助你快速定位应用中的性能瓶颈。一、命令概览它能做什么trace跟踪指定class-pattern/method-pattern所匹配的方法计算整条调用路径上每个节点的耗时。例如当你发现某个接口响应变慢时可以用trace直接展开该方法内部每个子调用的耗时一眼看出瓶颈究竟出在哪个子方法、哪个 JDK 调用甚至哪一行代码上。与watch、stack类似trace本质是字节码增强 方法调用前后埋点计时从源码看TraceAdviceListener 实现了InvokeTraceable接口在被观测方法体内每个方法调用的前后注入回调分别触发invokeBeforeTracing、invokeAfterTracing、invokeThrowTracing三个时机从而精确记录每个子调用的起止时间与抛异常情况。二、参数总览参数说明class-pattern类名表达式匹配method-pattern方法名表达式匹配condition-express条件表达式[E]开启正则表达式匹配默认是通配符匹配[n:]命令执行次数限制默认 100 次#cost方法执行耗时毫秒[c:]指定 classloader 的 hash 值只增强该 classloader 加载的类[m arg]匹配类的最大数量默认 50长格式为[maxMatch arg]--skipJDKMethod value是否跳过 JDK 方法追踪默认true--exclude-class-pattern排除指定类的匹配--listenerId指定监听器 ID用于动态 trace3.3.0-v打印条件表达式及其执行结果的详细信息默认false-p/--path路径追踪模式可指定多个路径匹配模式-L/--lazy惰性增强类尚未加载时启用待类加载后再增强其中m的默认值 50 在 EnhancerCommand.java 中通过DefaultValue(50)定义skipJDKMethod默认值true在 TraceCommand.java 中定义。--exclude-class-pattern、-v、--listenerId、--timeout、--lazy等通用选项继承自EnhancerCommandwatch/trace/monitor/stack/tt五个命令均支持。关于条件表达式condition-express是 trace 的一个重要特性它支持OGNL 语法。例如可以写出params[0]0这样的表达式只要符合 OGNL 语法即可。条件表达式中的核心变量来自Advice类详见 表达式核心变量说明变量说明loader当前调用类的 ClassLoaderclazz当前调用类的引用method当前调用方法的引用target当前调用类的实例params当前调用的参数数组无参数时为空数组returnObj正常返回时的返回值void返回时为nullthrowExp抛出异常时的异常对象isBefore/isThrow/isReturn方法执行阶段标记从 AbstractTraceAdviceListener.finishing() 可以看出底层逻辑方法执行结束后先通过threadLocalWatch.costInMillis()计算出本次调用的总耗时cost再调用isConditionMet(command.getConditionExpress(), advice, cost)判断条件表达式是否成立——表达式可以引用Advice中的任意变量也可以引用#cost这一特殊变量只有条件为真时才输出 trace 结果。很多时候我们只关心耗时超过某阈值的 trace 结果例如trace *StringUtils isBlank #cost100表示只有当执行时间超过 100ms 时才输出 trace 结果。watch/stack/trace三个命令都支持#cost。三、快速开始运行 Demo先启动官方提供的math-game演示程序见 Quick Start。该程序源码位于 math-game/src/main/java/demo/MathGame.javamain方法循环调用run()run()内部生成随机数并调用primeFactors()求质因数、再调用print()打印。启动后另开终端连接 Arthas即可执行下面的 trace 命令。四、实战示例1. 基础用法trace 方法$ trace demo.MathGame run Press Q or CtrlC to abort. Affect(class-cnt:1 , method-cnt:1) cost in 28 ms. ---ts2019-12-04 00:45:08;thread_namemain;id1;is_daemonfalse;priority5;TCCLsun.misc.Launcher$AppClassLoader3d4eac69 ---[0.617465ms] demo.MathGame:run() ---[0.078946ms] demo.MathGame:primeFactors() #24 [throws Exception] ---ts2019-12-04 00:45:09;thread_namemain;id1;is_daemonfalse;priority5;TCCLsun.misc.Launcher$AppClassLoader3d4eac69 ---[1.276874ms] demo.MathGame:run() ---[0.03752ms] demo.MathGame:primeFactors() #24 [throws Exception]输出解读每条记录以---开头包含时间戳ts、线程名、线程 id、是否守护线程、优先级、线程上下文类加载器等信息。随后是树形调用路径[耗时] 类名:方法名() 行号。这里的#24表示在run()函数源码的第 24 行调用了primeFactors()——对照 MathGame.java 第 24 行ListInteger primeFactors primeFactors(number);完全吻合。[throws Exception]表示该调用抛出了异常primeFactors对小于 2 的数会抛出IllegalArgumentException对应源码第 46 行的throw语句与文档示例中的#46一致。2. 限制匹配的类数量-m/--maxMatch当通配符匹配到大量类时可以用-m 1限制只增强匹配到的第一个类避免误增强多个类$ trace demo.MathGame run -m 1 Press Q or CtrlC to abort. Affect(class count: 1 , method count: 1) cost in 412 ms, listenerId: 4 ---ts2022-12-25 21:00:00;thread_namemain;id1;is_daemonfalse;priority5;TCCLsun.misc.Launcher$AppClassLoaderb4aac2 ---[0.762093ms] demo.MathGame:run() ---[30.21% 0.230241ms] demo.MathGame:primeFactors() #46 [throws Exception]注意这里子节点还多了一个30.21%的百分比表示该子调用耗时占父方法总耗时的比例。-m默认值为 50--maxMatch超过该数量命令会停止增强并提示。3. 指定 ClassLoader 增强-c如果同一个类被多个 ClassLoader 加载可以先用sc -d查出目标类的 classloader hash再用-c只增强指定 ClassLoader 加载的那一份sc -d com.example.Foo trace -c 3d4eac69 com.example.Foo bar这在存在类冲突、多应用共享容器如 Tomcat 多个 webapp的场景下非常有用。4. 限制追踪次数-n如果方法被高频调用用-n限制 trace 输出的次数。例如-n 1表示收到一次 trace 结果后命令自动退出$ trace demo.MathGame run -n 1 Press Q or CtrlC to abort. Affect(class-cnt:1 , method-cnt:1) cost in 20 ms. ---ts2019-12-04 00:45:53;thread_namemain;id1;is_daemonfalse;priority5;TCCLsun.misc.Launcher$AppClassLoader3d4eac69 ---[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.-n的默认值为 100见 TraceCommand.java。达到上限后命令自动退出并打印提示。输出中第一层子调用使用---最后一个子调用使用---作为树形分支标记。5. 包含 JDK 方法--skipJDKMethod false默认情况下 trace 会跳过java.*等 JDK 方法的追踪以保持输出聚焦。如果想看方法内部对 JDK 方法的调用与耗时可以关闭跳过$ trace --skipJDKMethod false demo.MathGame run Press Q or CtrlC to abort. Affect(class-cnt:1 , method-cnt:1) cost in 60 ms. ---ts2019-12-04 00:44:41;thread_namemain;id1;is_daemonfalse;priority5;TCCLsun.misc.Launcher$AppClassLoader3d4eac69 ---[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 ---[min0.004539ms,max0.005778ms,total0.010317ms,count2] 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这样就能看到run()内部对Random.nextInt()、String.format()、StringBuilder.append()等 JDK 调用的逐项耗时非常适合排查 JDK 库方法层面的性能问题。--skipJDKMethod默认值true定义在 TraceCommand.java。6. 按耗时过滤#cost 10结合条件表达式过滤出慢调用$ trace demo.MathGame run #cost 10 Press CtrlC to abort. Affect(class-cnt:1 , method-cnt:1) cost in 41 ms. ---ts2018-12-04 01:12:02;thread_namemain;id1;is_daemonfalse;priority5;TCCLsun.misc.Launcher$AppClassLoader3d4eac69 ---[12.033735ms] demo.MathGame:run() ---[0.006783ms] java.util.Random:nextInt() ---[11.852594ms] demo.MathGame:primeFactors() ---[0.05447ms] demo.MathGame:print()只有整条调用路径总耗时超过 10ms 的结果才会被输出让你在压测或生产问题排查时聚焦真正慢的调用。五、输出结果细节解读[12.033735ms]表示该节点方法耗时 12.033735ms。[min0.005428ms,max0.094064ms,total0.105228ms,count3] demo:call()表示将同名的多次调用聚合成一行输出最短耗时、最长耗时、总耗时、调用次数如果该行出现throws Exception说明这些调用中抛出了异常。父方法总耗时可能不等于各子调用耗时之和因为 Arthas 自身注入的埋点字节码也要消耗时间详见下文耗时误差。输出中的行号#xx指向被观测方法源码中的调用行对照 MathGame.java 可逐行验证。六、多层追踪匹配多个类与方法默认情况下trace只追踪目标方法内部第一层的子调用不会逐层深入——因为多层追踪成本很高会导致最终需要追踪的类和方法数量爆炸。一个折中方案是用正则表达式同时匹配路径上的多个类和方法近似实现多层追踪效果Trace -E com.test.ClassA|org.test.ClassB method1|method2|method3其中-E开启正则匹配|表示或。此外-p/--path参数提供了路径追踪模式见 TraceCommand.java通过getPathTracingClassMatcher()将类模式与多个路径模式组合成Or匹配器同时getPathTracingMethodMatcher()返回TrueMatcher匹配所有方法从而实现对指定路径上多个类/方法的链式追踪并配合PathTraceAdviceListener输出结果。排除指定类--exclude-class-patternwatch/trace/monitor/stack/tt命令都支持--exclude-class-pattern参数用于排除不需要追踪的类。例如追踪所有 Filter 但排除某个具体的实现watch javax.servlet.Filter * --exclude-class-pattern com.demo.TestFilter在 EnhancerCommand.java 中该参数定义了排除类名模式并最终由getClassNameExcludeMatcher()生成排除匹配器见 TraceCommand.java。七、动态 trace逐层深入调用链3.3.0从 3.3.0 版本开始支持动态 trace可以先追踪上层方法拿到listenerId再在新终端用--listenerId把下一层方法挂载到同一个监听器上实现逐层深入。Step 1终端 1 执行trace demo.MathGame run注意输出中的listenerId: 1[arthas59161]$ trace demo.MathGame run Press Q or CtrlC to abort. Affect(class count: 1 , method count: 1) cost in 112 ms, listenerId: 1 ---ts2020-07-09 16:48:11;thread_namemain;id1;is_daemonfalse;priority5;TCCLsun.misc.Launcher$AppClassLoader3d4eac69 ---[1.389634ms] demo.MathGame:run() ---[0.123934ms] demo.MathGame:primeFactors() #24 [throws Exception] ---ts2020-07-09 16:48:12;thread_namemain;id1;is_daemonfalse;priority5;TCCLsun.misc.Launcher$AppClassLoader3d4eac69 ---[3.716391ms] demo.MathGame:run() ---[3.182813ms] demo.MathGame:primeFactors() #24 ---[0.167786ms] demo.MathGame:print() #25Step 2想钻入子方法primeFactors内部继续追踪新开终端 2通过telnet localhost 3658连接 Arthas使用相同listenerId追踪primeFactors[arthas59161]$ trace demo.MathGame primeFactors --listenerId 1 Press Q or CtrlC to abort. Affect(class count: 1 , method count: 1) cost in 34 ms, listenerId: 1此时终端 2 只打印增强成功信息Affect(class count: 1 , method count: 1)不直接输出结果。Step 3回到终端 1可以看到 trace 结果多了一层primeFactors内部的调用甚至能看到具体的throw语句---ts2020-07-09 16:49:29;thread_namemain;id1;is_daemonfalse;priority5;TCCLsun.misc.Launcher$AppClassLoader3d4eac69 ---[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 ---ts2020-07-09 16:49:30;thread_namemain;id1;is_daemonfalse;priority5;TCCLsun.misc.Launcher$AppClassLoader3d4eac69 ---[0.409446ms] demo.MathGame:run() ---[0.232606ms] demo.MathGame:primeFactors() #24 | ---[0.1294ms] demo.MathGame:primeFactors() ---[0.084025ms] demo.MathGame:print() #25通过反复指定listenerId可以一层一层向下深入。watch/tt/monitor等命令同样支持类似的动态监听机制。--listenerId选项定义在 EnhancerCommand.java。八、trace 结果耗时不准的原因分析有时你会发现父方法耗时大于所有子调用耗时之和例如$ trace demo.MathGame run -n 1 Affect(class count: 1 , method count: 1) cost in 66 ms, listenerId: 1 ---ts2021-02-08 11:27:36;thread_namemain;id1;is_daemonfalse;priority5;TCCLsun.misc.Launcher$AppClassLoader232204a1 --[0.705196ms] demo.MathGame:run() ---[0.152743ms] demo.MathGame:primeFactors() #24 --[0.145825ms] demo.MathGame:print() #250.705196 (0.152743 0.145825)剩下的时间去哪了主要有三方面原因未被追踪的方法默认会跳过java.*下的方法。加上--skipJDKMethod false可以把它们打印出来$ trace demo.MathGame run --skipJDKMethod false Affect(class count: 1 , method count: 1) cost in 35 ms, listenerId: 2 ---ts2021-02-08 11:27:48;thread_namemain;id1;is_daemonfalse;priority5;TCCLsun.misc.Launcher$AppClassLoader232204a1 --[0.810591ms] demo.MathGame:run() --[0.034568ms] java.util.Random:nextInt() #23 ---[0.119367ms] demo.MathGame:timeFactors() #24 [throws Exception] ---[0.017407ms] java.lang.StringBuilder:init() #28 --[0.127922ms] java.lang.String:format() #57 ---[min0.01419ms,max0.020221ms,total0.034411ms,count2] java.lang.StringBuilder:append() #57 --[0.021911ms] java.lang.Exception:getMessage() #57 ---[0.015643ms] java.lang.StringBuilder:toString() #57 --[0.086622ms] java.io.PrintStream:println() #57指令本身的耗时例如i、getfield等字节码指令的执行时间不会作为方法调用出现在 trace 结果中。JVM 暂停代码执行期间的 GC、进入同步块等导致的线程停顿。另外需要明确Arthas 的 trace不会扣除自身埋点所消耗的时间因此没有 JProfiler 等商业软件精确调用路径上的类和方法越多误差越大但用于定位瓶颈方向仍然非常有效。九、用-v排查无输出问题执行 trace 后没有任何输出通常有两种可能匹配到的函数根本没有被执行条件表达式的结果为false被过滤掉了。用户无法直接区分这两种情况。此时加上-v参数Arthas 会打印出条件表达式及其实际执行结果方便确认trace demo.MathGame run #cost 10 -v从 AbstractTraceAdviceListener.finishing() 的源码可以看到开启 verbose 后每次判定都会输出Condition express: ... , result: ...。watch/trace/monitor/stack/tt命令都支持-v参数其默认值为false见 EnhancerCommand.java。十、注意事项trace擅长帮助发现和定位系统中的性能缺陷但每次只能追踪第一层的方法调用动态 trace 可逐层扩展。3.3.0 之后支持动态 trace可向已有监听器追加新的匹配类/方法。目前不支持trace java.lang.Thread getName见 issue #1610官方认为该需求必要性不高且修复难度大暂不修复。除文档中的示例外trace还支持OuterClass$InnerClass内部类匹配写法以及-L/--lazy类未加载时延迟增强、--timeout自动退出超时时间等增强命令通用选项完整示例可见 TraceCommand.java 的Description注解。掌握以上参数与技巧后你可以用trace快速展开任意方法的调用树先用#cost 阈值过滤慢调用再用--skipJDKMethod false看清 JDK 调用细节最后通过动态 trace 逐层钻入瓶颈方法内部精准定位性能热点。【免费下载链接】arthasAlibaba Java Diagnostic Tool Arthas/Alibaba Java诊断利器Arthas项目地址: https://gitcode.com/gh_mirrors/ar/arthas创作声明：本文部分内容由AI辅助生成（AIGC），仅供参考