Arthas里Trace命令怎样工作？

时间：2025-03-21 07:48:11

转：/alibaba/arthas/issues/597

Trace只对匹配到的method内的 子method 做统计

常见的一个疑问是 trace命令为什么有时候输出有时候是只有一级的，有时候是多级的？

首先trace命令的原理是：对匹配到的method内的 子method 做统计。

比如这个简单的Demo类：

import ;

public class Demo {
    public static void main(String[] args) throws InterruptedException {
        Demo demo = new Demo();
        while (true) {
            (1);
            ();
        }
    }
    public void hello() {
        (().getName() + "hello");
    }
}

使用Arthas执行： 

[arthas@53021]$ trace  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=$AppClassLoader@18b4aac2
    `---[0.87036ms] :hello()
        +---[0.065448ms] :<init>() #21
        +---[0.043073ms] :getClass() #21
        +---[0.032071ms] :getName() #21
        +---[min=0.017019ms,max=0.033141ms,total=0.05016ms,count=2] :append() #21
        +---[0.027778ms] :toString() #21
        `---[0.150838ms] :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/: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/:()Ljava/lang/Class;
        14: invokevirtual #11                 // Method java/lang/:()Ljava/lang/String;
        17: invokevirtual #12                 // Method java/lang/:(Ljava/lang/String;)Ljava/lang/StringBuilder;
        20: ldc           #13                 // String hello
        22: invokevirtual #12                 // Method java/lang/:(Ljava/lang/String;)Ljava/lang/StringBuilder;
        25: invokevirtual #14                 // Method java/lang/:()Ljava/lang/String;
        28: invokevirtual #15                 // Method java/io/:(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) {
            (1);
            ();
        }
    }

    interface Hello {
        public void hello();
    }

    static class ClassA implements Hello {
        @Override
        public void hello() {
            (().getName() + "hello");
        }
    }

    static class ClassB {
        public void test() {
            (().getName() + "hello");
            new ClassA().hello();
        }
    }

    static class ClassC {
        public void test() {
            (().getName() + "hello");
            new ClassB().test();
        }
    }

    static class ClassD implements Hello {
        @Override
        public void hello() {
            (().getName() + "hello");
            new ClassC().test();
        }
    }
}

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

[arthas@56879]$ trace $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=$AppClassLoader@18b4aac2
    `---[1.223513ms] $ClassD:hello()
        +---[0.057014ms] :<init>() #50
        +---[0.049171ms] :getClass() #50
        +---[0.043581ms] :getName() #50
        +---[min=0.018325ms,max=0.050003ms,total=0.068328ms,count=2] :append() #50
        +---[0.031672ms] :toString() #50
        +---[0.322031ms] :println() #50
        +---[0.027559ms] $ClassC:<init>() #51
        `---[0.073821ms] $ClassC:test() #51

 下面用arthas来trace Hello接口

[arthas@56879]$ trace $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=$AppClassLoader@18b4aac2
    `---[2.135409ms] $ClassD:hello()
        +---[0.198961ms] :<init>() #50
        +---[0.025948ms] :getClass() #50
        +---[0.021643ms] :getName() #50
        +---[min=0.013371ms,max=0.025803ms,total=0.039174ms,count=2] :append() #50
        +---[0.018355ms] :toString() #50
        +---[0.336261ms] :println() #50
        +---[0.032237ms] $ClassC:<init>() #51
        `---[0.514644ms] $ClassC:test() #51
            `---[0.361152ms] $ClassA:hello()
                +---[0.022994ms] :<init>() #30
                +---[0.01856ms] :getClass() #30
                +---[0.018ms] :getName() #30
                +---[min=0.008311ms,max=0.020543ms,total=0.028854ms,count=2] :append() #30
                +---[0.016813ms] :toString() #30
                `---[0.039936ms] :println() #30

可以看到：

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

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

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

相关文章