Arthas里Trace命令怎样工作？

转：https://github.com/alibaba/arthas/issues/597

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执行： 

[arthas@53021]$ trace com.example.demoNoSuchMethodError.Demo hello  -n 5 --skipJDKMethod false
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 50 ms, listenerId: 2
`---ts=2022-01-10 11:20:35;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@18b4aac2
    `---[0.87036ms] com.example.demoNoSuchMethodError.Demo:hello()
        +---[0.065448ms] java.lang.StringBuilder:<init>() #21
        +---[0.043073ms] java.lang.Object:getClass() #21
        +---[0.032071ms] java.lang.Class:getName() #21
        +---[min=0.017019ms,max=0.033141ms,total=0.05016ms,count=2] java.lang.StringBuilder:append() #21
        +---[0.027778ms] java.lang.StringBuilder:toString() #21
        `---[0.150838ms] java.io.PrintStream:println() #21

 我们看下Demo里面Hello相关的字节码

public void hello();
    descriptor: ()V
    flags: ACC_PUBLIC
    Code:
      stack=3, locals=1, args_size=1
         0: getstatic     #7                  // Field java/lang/System.out:Ljava/io/PrintStream;
         3: new           #8                  // class java/lang/StringBuilder
         6: dup
         7: invokespecial #9                  // Method java/lang/StringBuilder."<init>":()V
        10: aload_0
        11: invokevirtual #10                 // Method java/lang/Object.getClass:()Ljava/lang/Class;
        14: invokevirtual #11                 // Method java/lang/Class.getName:()Ljava/lang/String;
        17: invokevirtual #12                 // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
        20: ldc           #13                 // String hello
        22: invokevirtual #12                 // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
        25: invokevirtual #14                 // Method java/lang/StringBuilder.toString:()Ljava/lang/String;
        28: invokevirtual #15                 // Method java/io/PrintStream.println:(Ljava/lang/String;)V
        31: return

可以看到：每一个invokeXXX都对应一个trace结果里的entry。

所以：trace实际上是在每一个invokeXXX前后插入代码，然后统计调用的时间

trace本身只能拿到当前method的字节码，所以它只能trace当前method里的 invokeXXX，再深层的invokeXXX，它并不能知道

为什么trace结果有时会有多层？

在下面demo里面，代码很简单：

• ClassD调用ClassC，ClassC调用ClassB，ClassB调用ClassA
• ClassD和ClassA实现了Hello接口

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 {
        @Override
        public void hello() {
            System.out.println(this.getClass().getName() + "hello");
            new ClassC().test();
        }
    }
}

下面用arthas执行，看到结果只有一层，符合预期

[arthas@56879]$ trace com.example.demoNoSuchMethodError.Demo$ClassD hello --skipJDKMethod false
Press Q or Ctrl+C to abort.
Affect(class count: 1 , method count: 1) cost in 41 ms, listenerId: 3
`---ts=2022-01-10 14:14:12;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@18b4aac2
    `---[1.223513ms] com.example.demoNoSuchMethodError.Demo$ClassD:hello()
        +---[0.057014ms] java.lang.StringBuilder:<init>() #50
        +---[0.049171ms] java.lang.Object:getClass() #50
        +---[0.043581ms] java.lang.Class:getName() #50
        +---[min=0.018325ms,max=0.050003ms,total=0.068328ms,count=2] java.lang.StringBuilder:append() #50
        +---[0.031672ms] java.lang.StringBuilder:toString() #50
        +---[0.322031ms] java.io.PrintStream:println() #50
        +---[0.027559ms] com.example.demoNoSuchMethodError.Demo$ClassC:<init>() #51
        `---[0.073821ms] com.example.demoNoSuchMethodError.Demo$ClassC:test() #51

 下面用arthas来trace Hello接口

[arthas@56879]$ trace com.example.demoNoSuchMethodError.Demo$Hello hello  -n 5 --skipJDKMethod false
Press Q or Ctrl+C to abort.
Affect(class count: 3 , method count: 2) cost in 56 ms, listenerId: 4
`---ts=2022-01-10 14:15:06;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@18b4aac2
    `---[2.135409ms] com.example.demoNoSuchMethodError.Demo$ClassD:hello()
        +---[0.198961ms] java.lang.StringBuilder:<init>() #50
        +---[0.025948ms] java.lang.Object:getClass() #50
        +---[0.021643ms] java.lang.Class:getName() #50
        +---[min=0.013371ms,max=0.025803ms,total=0.039174ms,count=2] java.lang.StringBuilder:append() #50
        +---[0.018355ms] java.lang.StringBuilder:toString() #50
        +---[0.336261ms] java.io.PrintStream:println() #50
        +---[0.032237ms] com.example.demoNoSuchMethodError.Demo$ClassC:<init>() #51
        `---[0.514644ms] com.example.demoNoSuchMethodError.Demo$ClassC:test() #51
            `---[0.361152ms] com.example.demoNoSuchMethodError.Demo$ClassA:hello()
                +---[0.022994ms] java.lang.StringBuilder:<init>() #30
                +---[0.01856ms] java.lang.Object:getClass() #30
                +---[0.018ms] java.lang.Class:getName() #30
                +---[min=0.008311ms,max=0.020543ms,total=0.028854ms,count=2] java.lang.StringBuilder:append() #30
                +---[0.016813ms] java.lang.StringBuilder:toString() #30
                `---[0.039936ms] java.io.PrintStream:println() #30

可以看到：

• 结果树有两层，一层是Demo$ClassD:hello()，另一层是Demo$ClassA:hello()

• 为什么ClassC/ClassB没有出现在结果树里？为什么树不是四层的？

  因为trace匹配的是Hello接口，只有ClassD和ClassA实现了Hello接口。