Arthas里 Trace 命令怎样工作的/ Trace命令的实现原理
hengyunabc opened this issue · 7 comments
3.3.0 版本后,增加动态trace功能,可以动态深入下一层: https://alibaba.github.io/arthas/trace.html
Trace只对匹配到的method内的 子method 做统计
常见的一个疑问是 trace命令为什么有时候输出有时候是只有一级的,有时候是多级的?
首先trace命令的原理是:对匹配到的method内的 子method 做统计。
比如这个简单的Demo
类:
import java.util.concurrent.TimeUnit;
public class Demo {
public static void main(String[] args) throws InterruptedException {
Demo demo = new Demo();
while (true) {
TimeUnit.SECONDS.sleep(1);
demo.hello();
}
}
public void hello() {
System.out.println(this.getClass().getName() + "hello");
}
}
使用arthas执行 trace Demo hello
:
结果是:
$ trace Demo hello
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 108 ms.
`---ts=2019-03-22 18:49:44;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@4e25154f
`---[1.477191ms] Demo:hello()
+---[0.035988ms] java.lang.Object:getClass()
+---[0.01844ms] java.lang.Class:getName()
+---[0.018744ms] java.lang.String:valueOf()
+---[0.023555ms] java.lang.StringBuilder:<init>()
+---[0.022698ms] java.lang.StringBuilder:append()
+---[0.014707ms] java.lang.StringBuilder:toString()
`---[0.091016ms] java.io.PrintStream:println()
我们看下Demo类的字节码:
public void hello();
descriptor: ()V
flags: ACC_PUBLIC
Code:
stack=4, locals=1, args_size=1
0: getstatic #37 // Field java/lang/System.out:Ljava/io/PrintStream;
3: new #43 // class java/lang/StringBuilder
6: dup
7: aload_0
8: invokevirtual #45 // Method java/lang/Object.getClass:()Ljava/lang/Class;
11: invokevirtual #49 // Method java/lang/Class.getName:()Ljava/lang/String;
14: invokestatic #55 // Method java/lang/String.valueOf:(Ljava/lang/Object;)Ljava/lang/String;
17: invokespecial #61 // Method java/lang/StringBuilder."<init>":(Ljava/lang/String;)V
20: ldc #64 // String hello
22: invokevirtual #65 // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
25: invokevirtual #69 // Method java/lang/StringBuilder.toString:()Ljava/lang/String;
28: invokevirtual #72 // Method java/io/PrintStream.println:(Ljava/lang/String;)V
31: return
可以看到每一个invokevirtual
都对应一个 trace结果里的entry。
所以,trace实际上是在每一个invokevirtual
前后插入代码,然后统计调用的时间。
trace本身只能拿到当前method的字节码,所以它只能trace当前method里的 invokevirtual
,再深层的invokevirtual
,它并不能知道。
为什么trace结果有时会有多层?
在下面的Demo
里,代码很简单:
ClassD
调用ClassC
,ClassC
调用ClassB
,ClassB
调用ClassA
ClassD
和ClassA
实现了Hello
接口
import java.util.concurrent.TimeUnit;
public class Demo {
public static void main(String[] args) throws InterruptedException {
ClassD d = new ClassD();
while (true) {
TimeUnit.SECONDS.sleep(1);
d.hello();
}
}
interface Hello {
public void hello();
}
static class ClassA implements Hello {
@Override
public void hello() {
System.out.println(this.getClass().getName() + "hello");
}
}
static class ClassB {
public void test() {
System.out.println(this.getClass().getName() + "hello");
new ClassA().hello();
}
}
static class ClassC {
public void test() {
System.out.println(this.getClass().getName() + "hello");
new ClassB().test();
}
}
static class ClassD implements Hello {
public void hello() {
System.out.println(this.getClass().getName() + "hello");
new ClassC().test();
}
}
}
下面用arthas执行 trace Demo$ClassD hello
,可以看到结果树是只有一层的,符合预期:
$ trace Demo$ClassD hello
Press Q or Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 96 ms.
`---ts=2019-03-22 19:04:19;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@4e25154f
`---[3.911624ms] Demo$ClassD:hello()
+---[0.032104ms] java.lang.Object:getClass()
+---[0.016964ms] java.lang.Class:getName()
+---[0.016445ms] java.lang.String:valueOf()
+---[0.015006ms] java.lang.StringBuilder:<init>()
+---[0.01918ms] java.lang.StringBuilder:append()
+---[0.01548ms] java.lang.StringBuilder:toString()
+---[1.409546ms] java.io.PrintStream:println()
+---[0.01654ms] Demo$ClassC:<init>()
`---[0.688504ms] Demo$ClassC:test()
下面再用arthas来trace Hello
接口:trace Demo$Hello hello
$ trace Demo$Hello hello
Press Q or Ctrl+C to abort.
Affect(class-cnt:2 , method-cnt:2) cost in 29 ms.
`---ts=2019-03-22 19:04:40;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@4e25154f
`---[1.019782ms] Demo$ClassD:hello()
+---[0.008038ms] java.lang.Object:getClass()
+---[0.008512ms] java.lang.Class:getName()
+---[0.00866ms] java.lang.String:valueOf()
+---[0.02074ms] java.lang.StringBuilder:<init>()
+---[0.01381ms] java.lang.StringBuilder:append()
+---[0.006114ms] java.lang.StringBuilder:toString()
+---[0.110468ms] java.io.PrintStream:println()
+---[0.009324ms] Demo$ClassC:<init>()
`---[0.59506ms] Demo$ClassC:test()
`---[0.416302ms] Demo$ClassA:hello()
+---[0.00866ms] java.lang.Object:getClass()
+---[0.01141ms] java.lang.Class:getName()
+---[0.012544ms] java.lang.String:valueOf()
+---[0.013024ms] java.lang.StringBuilder:<init>()
+---[0.065776ms] java.lang.StringBuilder:append()
+---[0.016712ms] java.lang.StringBuilder:toString()
`---[0.060616ms] java.io.PrintStream:println()
可以看到:
- 结果树有两层,一层是
Demo$ClassD:hello()
,另一层是Demo$ClassA:hello()
为什么ClassC
/ClassB
没有出现在结果树里?为什么树不是四层的?
因为trace匹配的是Hello
接口,只有ClassD
和ClassA
实现了Hello
接口。
总结
- trace匹配到了多个class,多个method
- 多个method在同一个线程里被调用,一个method就会是trace结果里的一层
- 因为trace在
ThreadLocal
里记录了树的结点信息,所以在一个线程里调用多个匹配到的method,就会形成一个树
Trace 还有两个常见问题:
- Trace多个类和函数: #443 (comment)
- 怎么区分重载函数:#434
以上面的demo为例,如果想把整个4层的调用树列出来,那么可以执行
trace -E 'Demo\$Hello|Demo\$ClassB|Demo\$ClassC' 'hello|test'
那么会把完整的调用树打印出来:
$ trace -E 'Demo\$Hello|Demo\$ClassB|Demo\$ClassC' 'hello|test'
Press Q or Ctrl+C to abort.
Affect(class-cnt:4 , method-cnt:4) cost in 99 ms.
`---ts=2019-03-22 19:17:53;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@4e25154f
`---[3.07526ms] Demo$ClassD:hello()
+---[0.034132ms] java.lang.Object:getClass()
+---[0.015133ms] java.lang.Class:getName()
+---[0.012802ms] java.lang.String:valueOf()
+---[0.010077ms] java.lang.StringBuilder:<init>()
+---[0.010013ms] java.lang.StringBuilder:append()
+---[0.010582ms] java.lang.StringBuilder:toString()
+---[0.17528ms] java.io.PrintStream:println()
+---[0.022878ms] Demo$ClassC:<init>()
`---[2.404445ms] Demo$ClassC:test()
`---[2.158ms] Demo$ClassC:test()
+---[0.01101ms] java.lang.Object:getClass()
+---[0.016783ms] java.lang.Class:getName()
+---[0.016797ms] java.lang.String:valueOf()
+---[0.020633ms] java.lang.StringBuilder:<init>()
+---[0.017495ms] java.lang.StringBuilder:append()
+---[0.010945ms] java.lang.StringBuilder:toString()
+---[0.043742ms] java.io.PrintStream:println()
+---[0.019857ms] Demo$ClassB:<init>()
`---[1.741185ms] Demo$ClassB:test()
`---[1.581065ms] Demo$ClassB:test()
+---[0.173202ms] java.lang.Object:getClass()
+---[0.019643ms] java.lang.Class:getName()
+---[0.019705ms] java.lang.String:valueOf()
+---[0.013422ms] java.lang.StringBuilder:<init>()
+---[0.021875ms] java.lang.StringBuilder:append()
+---[0.096128ms] java.lang.StringBuilder:toString()
+---[0.050018ms] java.io.PrintStream:println()
+---[0.02202ms] Demo$ClassA:<init>()
`---[0.798537ms] Demo$ClassA:hello()
`---[0.641463ms] Demo$ClassA:hello()
+---[0.010265ms] java.lang.Object:getClass()
+---[0.02994ms] java.lang.Class:getName()
+---[0.015822ms] java.lang.String:valueOf()
+---[0.034097ms] java.lang.StringBuilder:<init>()
+---[0.015282ms] java.lang.StringBuilder:append()
+---[0.010235ms] java.lang.StringBuilder:toString()
`---[0.038225ms] java.io.PrintStream:println()
trace的方法是有入参的,所以trace是如何构造参数的?
trace的方法是有入参的,所以trace是如何构造参数的?
trace不支持获取入参。
trace的方法是有入参的,所以trace是如何构造参数的?
trace不支持获取入参。
我trace的方法也是有入参的,不太明白具体入参怎么写?
min/max/total/count 意义解析
public class Test {
public static void main(String[] args) {
for(;;) {
aaa();
}
}
public static void aaa() {
for(int i = 1; i < 10; ++i) {
bbb(i);
System.err.println(i);
}
}
public static void bbb(int i ) {
try {
Thread.sleep(i * 100);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
启动上面的demo,然后执行 trace Test aaa
,可以看到下面的输出结果:
[arthas@25252]$ trace Test aaa
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 87 ms, listenerId: 1
`---ts=2021-06-09 15:51:33;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@73d16e93
`---[4527.809232ms] Test:aaa()
`---[min=105.151799ms,max=900.906267ms,total=4525.33612ms,count=9] Test:bbb() #12
那么这一行红色的是什么意思呢?
- count=9,表示在
aaa
里调用了bbb
函数9次 min=105.151799ms
表示在9次调用里,时间最少的是105
毫秒max=900.906267ms
表示在9次调用里,时间最多的是900
毫秒4525.33612ms
表示9次调用,总耗时是4525
毫秒
请问下,trace命令对性能的压力大不大,目前碰到线程池超时的线上问题,很难复现,想要通过异步任务 + trace指令来排查和记录问题,但是担心这种方式会有大的性能瓶颈/