阿尔萨斯 原理探究 仿写arthas-trace

发表于 | 分类于

前言

arthas 中 trace 可以监控一个方法内部调用路径，并输出方法路径上的每个节点上耗时.

1
2
3
4
5
6
7
8
$ trace demo.MathGame run
Press Ctrl+C to abort.
Affect(class-cnt:1 , method-cnt:1) cost in 42 ms.
`---ts=2018-12-04 00:44:17;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@3d4eac69
    `---[10.611029ms] demo.MathGame:run()
        +---[0.05638ms] java.util.Random:nextInt()
        +---[10.036885ms] demo.MathGame:primeFactors()
        `---[0.170316ms] demo.MathGame:print()

在刚接触到这个功能时，我在想这不就是Spring中的切面编程，对方法进行加强嘛！！

不过还是有点想当然，首先要注意的是我们监控的方法所在的虚拟机没有重启，更没有对一个方法加上注解或者通过配置文件来加强这个方法，因此trace是在虚拟机层面上的AOP！！还好这部分我们在上一篇已经说到过了，那么还有一个问题如何监控方法内部的调用路径呢？？关于这个点我会在后面的章节分享我的做法。代码上传至：github

如何获得一个方法的调用路径

假设我们的doAdd()方法中有以下方法：

1
2
3
4
5
6
7
8
9
10
public int doAdd(int x, int y) throws Exception{
    Thread.sleep(1000);
    test();
    return  x+y;
}

public void test() throws Exception{
    Thread.sleep(1000);
    //System.out.println("");
}

arthas匹配到的函数里的子调用，并不会向下trace多层，因此我们只考虑如何知道doAdd中子调用链路。有些同学可能会想到用 stackTraceElement 来实现：

1
StackTraceElement[] stackTraceElement =  Thread.currentThread().getStackTrace();

但是getStackTrace只能获取到在调用该语句之前还未出栈的栈帧。

回想一下在前面《阿尔萨斯 原理探究 asm再认识（转载）》中，我们通过重写MethodVisitor实现对一个方法的字节码的修改：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
static class TestMethodVisitor extends MethodVisitor {
    public TestMethodVisitor(MethodVisitor mv) {
        super(Opcodes.ASM5, mv);
    }

    @Override
    public void visitCode() {
        //方法体内开始时调用
        super.visitCode();
    }

    @Override
    public void visitInsn(int opcode) {
        //每执行一个指令都会调用
        super.visitInsn(opcode);
    }
}

那么MethodVisitor会不会有对子方法调用的入口呢？的确是有的这个入口，visitMethodInsn:访问方法操作指令

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
//opcode：为INVOKESPECIAL,INVOKESTATIC,INVOKEVIRTUAL,INVOKEINTERFACE;
//owner:方法拥有者的名称;
//name:方法名称;
//descriptor:方法描述，参数和返回值;
//isInterface；是否是接口; 
public void visitMethodInsn(final int opcode,final String owner,
         final String name,final String descriptor,final boolean isInterface) {
    if (api < Opcodes.ASM5) {
      if (isInterface != (opcode == Opcodes.INVOKEINTERFACE)) {
        throw new IllegalArgumentException("INVOKESPECIAL/STATIC on interfaces requires ASM5");
      }
      visitMethodInsn(opcode, owner, name, descriptor);
      return;
    }
    if (mv != null) {
      mv.visitMethodInsn(opcode, owner, name, descriptor, isInterface);
    }
  }

通过这个方法，我们可以监控到所有子调用的信息了，但是要注意asm中只有访问方法操作指令，并没有方法结束的调用指令。注意visitInsn通过opcode来判断指令是否为return只能知道当前方法的结束，但是不能获取子调用的结束的方法，这么说可能会有点绕，那上面的doAdd来解释：

asm 中的MethodVisitor的确可以通过visitCode对doAdd执行前进行干预，也可以通过visitInsn中的opcode知道doAdd的结束操作。那么一前一后就可以对方法进行监控了啊！！

1
2
3
4
5
6
7
doAdd(int x, int y){
	记录方法开始时间 --通过visitCode
	Thread.sleep(1000);
	test();
    记录方法结束时间，打印，结束时间-开始时间 --通过visitInsn中的opcode
    return x+y;
}

但是doAdd中的子调用（ Thread.sleep、test）却只有通过visitMethodInsn在子调用开始之前进行干预，也就是如下：

1
2
3
4
5
6
7
8
9
10
11
12
doAdd(int x, int y){
	记录doAdd方法开始时间 --通过visitCode
	
	记录Thread.sleep方法开始时间 --通过visitMethodInsn
	Thread.sleep(1000);
	
	记录test方法开始时间 --通过visitMethodInsn
	test();
	
    记录doAdd方法结束时间，打印，结束时间-开始时间 --通过visitInsn中的opcode
    return x+y;
}

其实这里可以灵活一点，就是每个方法除了记录自己的开始时间，也把上一个的结束时间记录一下即可：​ 

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
doAdd(int x, int y){
	记录doAdd方法开始时间 --通过visitCode
        
    记录Thread.sleep方法开始时间 --通过visitMethodInsn
    记录（因为Thrad.sleep前面没有方法了，所以可以随便设置初始方法）方法结束的时间
    Thread.sleep(1000);
	
    记录Thread.slepp方法结束的时间
    记录test方法开始时间 --通过visitMethodInsn
    test();
	
    记录test方法结束的时间
    记录doAdd方法结束时间，打印，结束时间-开始时间 --通过visitInsn中的opcode
	return x+y;
}

如果没能理解可以看后面详细的代码。

TraceAgentMain

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
public class TraceAgentMain {

    public static void agentmain(String agentArgs, Instrumentation inst)
            throws Exception {
        String methodName = agentArgs.substring(agentArgs.lastIndexOf(".")+1,agentArgs.length());
        String className = agentArgs.substring(0,agentArgs.lastIndexOf("."));
        inst.addTransformer(new TraceTransformer(className, methodName), true);

        inst.retransformClasses(getClassByRedefinePath(className));
    }

    public static Class<?> getClassByRedefinePath(String targetClassName) throws Exception{
        return Class.forName(targetClassName);
    }

}

TraceTransformer

TraceTransformer主要编写了类转换的实现，通过自定义的TraceClassVisitor。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
public class TraceTransformer implements ClassFileTransformer {

    public String className_i ;
    public String methodName_i ;

    public TraceTransformer(String cn , String mn){
        className_i = cn;
        methodName_i = mn;
    }

    @Override
    public byte[] transform(ClassLoader loader, String className, Class<?> classBeingRedefined,
                            ProtectionDomain protectionDomain, byte[] classfileBuffer) {
        className = className.replace("/", ".");

        if(className.equals(className_i)){
            ClassReader reader = new ClassReader(classfileBuffer);
            ClassWriter writer = new ClassWriter(reader, ClassWriter.COMPUTE_MAXS);
            TraceClassVisitor traceClassVisitor = new TraceClassVisitor(writer,methodName_i);
            reader.accept(traceClassVisitor, ClassReader.SKIP_FRAMES);

            return writer.toByteArray();
        }
        return classfileBuffer;
    }
}

TraceClassVisitor

在进行方法的访问时，对方法进行加强！

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
public class TraceClassVisitor extends ClassVisitor {

    public String methodName ;

    public TraceClassVisitor(final ClassVisitor cv, String mn) {
        super(ASM5, cv);
        methodName = mn;
    }

    @Override
    public MethodVisitor visitMethod(final int access, final String name, final String desc, final String signature, final String[] exceptions) {
        MethodVisitor mv = super.visitMethod(access, name, desc, signature, exceptions);
        if (name.equals(methodName)) {
            return new TraceMethodVisitor(mv,name);
        }
        return mv;
    }
}

TraceMethodVisitor

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
public class TraceMethodVisitor extends MethodVisitor {

    public String name ;
    public int preCode = -1 ;
    public int lastCode = -1 ;

    protected TraceMethodVisitor(MethodVisitor mv, String n) {
        super(Opcodes.ASM5, mv);
        name = n;
    }

    @Override
    public void visitCode() {
        //方法体内开始时调用
        mv.visitFieldInsn(GETSTATIC, "java/lang/System", "out", "Ljava/io/PrintStream;");
        mv.visitLdcInsn(name);
        mv.visitMethodInsn(INVOKEVIRTUAL, "java/io/PrintStream", "println", "(Ljava/lang/String;)V", false);

        mv.visitLdcInsn(name);
        mv.visitMethodInsn(INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false);
        mv.visitMethodInsn(INVOKESTATIC, "agent/Utils/ITimeUtil", "setStartTime", "(Ljava/lang/String;J)V", false);
        super.visitCode();
    }

    @Override
    public void visitInsn(int opcode) {
        // 每执行一个指令都会调用 , 如果是void方法的return应该是RETURN，如果是return int 那应该是IRETURN
        // 因为这里只是演示，所以线上的代码需要把返回的情况全部写一遍！！（FRETURN、DRETURN等等）
        // 这里可以使用范围表示是一个返回指令
        if (opcode <= Opcodes.RETURN && opcode >= Opcodes.IRETURN) {

            //输出最后一个方法的运行时间
            mv.visitLdcInsn(String.valueOf(lastCode));
            mv.visitMethodInsn(INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false);
            mv.visitMethodInsn(INVOKESTATIC, "agent/Utils/ITimeUtil", "setEndTime", "(Ljava/lang/String;J)V", false);

            mv.visitFieldInsn(GETSTATIC, "java/lang/System", "out", "Ljava/io/PrintStream;");
            mv.visitLdcInsn(String.valueOf(lastCode));
            mv.visitMethodInsn(INVOKESTATIC, "agent/Utils/ITimeUtil", "getCostTime", "(Ljava/lang/String;)Ljava/lang/String;", false);
            mv.visitMethodInsn(INVOKEVIRTUAL, "java/io/PrintStream", "println", "(Ljava/lang/String;)V", false);

            // ----------------------
            mv.visitFieldInsn(GETSTATIC, "java/lang/System", "out", "Ljava/io/PrintStream;");
            mv.visitLdcInsn("almost time cost：");
            mv.visitMethodInsn(INVOKEVIRTUAL, "java/io/PrintStream", "println", "(Ljava/lang/String;)V", false);

            //输出整体方法的时间
            mv.visitLdcInsn(name);
            mv.visitMethodInsn(INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false);
            mv.visitMethodInsn(INVOKESTATIC, "agent/Utils/ITimeUtil", "setEndTime", "(Ljava/lang/String;J)V", false);

            mv.visitFieldInsn(GETSTATIC, "java/lang/System", "out", "Ljava/io/PrintStream;");
            mv.visitLdcInsn(name);
            mv.visitMethodInsn(INVOKESTATIC, "agent/Utils/ITimeUtil", "getCostTime", "(Ljava/lang/String;)Ljava/lang/String;", false);
            mv.visitMethodInsn(INVOKEVIRTUAL, "java/io/PrintStream", "println", "(Ljava/lang/String;)V", false);
        }
        super.visitInsn(opcode);
    }

    @Override
    public void visitMethodInsn(
            final int opcode,
            final String owner,
            final String name,
            final String descriptor,
            final boolean isInterface) {
        // SetEndTime , 第一次过滤掉，因为是没有方法体的
        if(preCode!=-1) {
            mv.visitLdcInsn(String.valueOf(preCode));
            mv.visitMethodInsn(INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false);
            mv.visitMethodInsn(INVOKESTATIC, "agent/Utils/ITimeUtil", "setEndTime", "(Ljava/lang/String;J)V", false);

            // print Cost time
            mv.visitFieldInsn(GETSTATIC, "java/lang/System", "out", "Ljava/io/PrintStream;");
            mv.visitLdcInsn(String.valueOf(preCode));
            mv.visitMethodInsn(INVOKESTATIC, "agent/Utils/ITimeUtil", "getCostTime", "(Ljava/lang/String;)Ljava/lang/String;", false);
            mv.visitMethodInsn(INVOKEVIRTUAL, "java/io/PrintStream", "println", "(Ljava/lang/String;)V", false);
        }

        // 输出当前方法名
        mv.visitFieldInsn(GETSTATIC, "java/lang/System", "out", "Ljava/io/PrintStream;");
        mv.visitLdcInsn("-|"+owner.replace("/","")+"@"+name);
        mv.visitMethodInsn(INVOKEVIRTUAL, "java/io/PrintStream", "println", "(Ljava/lang/String;)V", false);

        // 当前方法set进去
        mv.visitLdcInsn(String.valueOf(opcode));
        mv.visitMethodInsn(INVOKESTATIC, "java/lang/System", "nanoTime", "()J", false);
        mv.visitMethodInsn(INVOKESTATIC, "agent/Utils/ITimeUtil", "setStartTime", "(Ljava/lang/String;J)V", false);

        preCode = lastCode = opcode;
        super.visitMethodInsn(opcode,owner,name,descriptor,isInterface);
    }

}

实现效果

启动Main函数：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
public class Main {

    public static void main( String[] args ) throws Exception {

        Job demo = new Job();
        while (true) {
            //demo.doAdd(0,1);
            System.out.println(demo.doAdd(1,2));
            System.out.println(demo.doDelet(2,1));
            System.out.println("-------------------");
            Thread.sleep(1000);
        }
    }
}

Job的实现：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
public class Job {
    public int doAdd(int x, int y) throws Exception{
        Thread.sleep(1000);
        test();
        return  x+y;

    }

    public int doDelet(int x, int y) throws Exception{
        Thread.sleep(500);
        return x-y;
    }

    public void test() throws Exception{
        StackTraceElement[] stackTraceElement =  Thread.currentThread().getStackTrace();
        Thread.sleep(1000);
        //System.out.println("");
    }
}

通知目标主机：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
public class Iarthas {

    public static void main(String[] args) throws Exception{
        trace("agent.Job.doAdd","29212");
    }


    public static void trace(String methodPath ,String pid)
            throws IOException, AttachNotSupportedException, AgentLoadException, AgentInitializationException {
        VirtualMachine virtualMachine = VirtualMachine.attach(pid);
        virtualMachine.loadAgent("F:\\iarthas\\target\\agentTest-1.0-SNAPSHOT.jar", methodPath);
        virtualMachine.detach();
    }

    public static void attach(String classPath, String pid)
            throws IOException, AttachNotSupportedException, AgentLoadException, AgentInitializationException {
        VirtualMachine virtualMachine = VirtualMachine.attach(pid);
        virtualMachine.loadAgent("C:\\Users\\64669\\Desktop\\arthas\\redefine.jar", classPath);
        virtualMachine.detach();
    }
}

运行结果：一开始没有输出运行时间，当 trace(“agent.Job.doAdd”,”29212”)后 可以对Job类中的方法进行监控，输出子调用的过程：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
3
1
-------------------
3
1
-------------------
doAdd
-|javalangThread@sleep
--|method  Cost: 1000.0282599999999 ms
-|agentJob@test
--|method  Cost: 1000.0648309999999 ms
almost time cost：
--|method  Cost: 2005.3643539999998 ms
3
1
-------------------
doAdd
-|javalangThread@sleep
--|method  Cost: 1000.148779 ms
-|agentJob@test
--|method  Cost: 999.828502 ms
almost time cost：
--|method  Cost: 2000.759687 ms
3
1
-------------------