Pinpoint中的方法self执行时间包含外层拦截器自身的执行时间吗?

1,141 阅读3分钟
  1. 问题描述

Pinpoint调用链路界面上的Self时间包括拦截器处理时间吗?先看下图:

其中方法执行时间Self描述是这样的:

Duration of the method call from entry to exit, excluding time consumed in nested methods call

我们画个图来描述下这个过程如下:

这里的Self 时间实际上 = t1 - t2 - t3。

上述简单场景很容易理解,但是实际场景往往并非这么简单。例如,上图中的real method真实场景中往往是个拦截器(代理对象),那么这里的Self 时间是否包含拦截器自身的执行时间呢?

这似乎是一个触及灵魂的问题!

  1. 问题分析

要弄清楚这个问题,我们就要回到上述Self 方法统计的本质。

我们知道Pinpoint是通过字节码技术动态对方法的进行修改的,也就是说本质上也是给方法体添加了拦截器来统计方法执行时间的。所以上述问题本质上是AOP动态代理和字节码注入(代理)的执行先后顺序问题

说到这里有经验的同学可能一下子就知道答案了,Self = t11 - t2 - t3。原因是字节码技术是更底层的技术,他作用在class上,而AOP只是一种动态代理技术,他作用在容器或框架上。

确实是这样的,为了验证以上结果,我们拿实际代码测试一下看看(因为Pinpoint太过臃肿,我们自己实现个简答的javaagent来模拟下Pinpoint的方法注入)。

  1. 编写动态字节码注入代码

首先来写一段agent代码,

/**
 * @author zhangjb
 */
public class PreMainTraceAgent {

    public static void premain(String agentArgs, Instrumentation inst) {
        inst.addTransformer(new DefineTransformer(), true);
    }

    static class DefineTransformer implements ClassFileTransformer {

        @Override
        public byte[] transform(ClassLoader loader, String className, Class<?> classBeingRedefined, ProtectionDomain protectionDomain, byte[] classfileBuffer) throws IllegalClassFormatException {

            // 这里我们拦截AutoConfigDemo类,并在schedule方法入口打印:In agent transform
            if ("cn/gov/zcy/dubbotest/after/AutoConfigDemo".equalsIgnoreCase(className)) {
                try {
                    String methodName = "schedule";
                    ClassPool cp = ClassPool.getDefault();
                    cp.insertClassPath(new LoaderClassPath(loader));
                    cp.insertClassPath(new ByteArrayClassPath(className, classfileBuffer));
                    CtClass ctclass = cp.getCtClass(className.replaceAll("/", "."));
                    CtMethod ctmethod = ctclass.getDeclaredMethod(methodName);
                    // 动态给方法入口增加代码
                    ctmethod.insertBefore("{ System.out.println(\"In agent transform\");  }");

                    return ctclass.toBytecode();
                } catch (Exception e) {
                    e.printStackTrace();
                }
            }

            return classfileBuffer;
        }
    }
}

为了能够作用到javaagent,还需要执行maven 插件:

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <parent>
        <artifactId>dubbo-test</artifactId>
        <groupId>cn.gov.zcy</groupId>
        <version>1.0.0-SNAPSHOT</version>
    </parent>
    <modelVersion>4.0.0</modelVersion>

    <artifactId>dubbo-test-agent</artifactId>

    <dependencies>
        <dependency>
            <groupId>javassist</groupId>
            <artifactId>javassist</artifactId>
            <version>3.12.1.GA</version>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-jar-plugin</artifactId>
                <version>3.1.0</version>
                <configuration>
                    <archive>
                        <manifest>
                            <addClasspath>true</addClasspath>
                        </manifest>
                        <manifestEntries>
                            <Premain-Class>com.jimbean.test.agent.PreMainTraceAgent</Premain-Class>
                            <Agent-Class>com.jimbean.test.agent.PreMainTraceAgent</Agent-Class>
                            <Can-Redefine-Classes>true</Can-Redefine-Classes>
                            <Can-Retransform-Classes>true</Can-Retransform-Classes>
                        </manifestEntries>
                    </archive>
                </configuration>
            </plugin>
        </plugins>
    </build>
</project>

说明:javaagent规范非本次重点,读者可以自行百度。

完成以上步骤后,我们将其打包成一个lib就可以使用了。

  1. 编写AOP动态代理代码

接下来我们来使用Spring 写个AOP的示例。

4.1. 定义一个定时器


@Component
public class AutoConfigDemo {

  // 定时任务每30秒执行一次
    @Scheduled(cron="0/30 * *  * * ? ")
    public void schedule(){

        System.out.println("In method schedule");
    }
}

这里小编使用的Springboot编写的工程,上述@Scheduled注解还需要通过@EnableScheduling进行生效。

@EnableScheduling
@SpringBootApplication(exclude= {DataSourceAutoConfiguration.class})
public class WebApplication {
    /**
     * 启动SpringBoot程序
     */
    public static void main(String[] args) {
        new SpringApplication(WebApplication.class).run(args);
        System.out.println("WebApplication start success...");
    }

}

4.2. 编写定时方法拦截器

@Aspect
@Component
public final class AspectTest {

    // 拦截@Scheduled注解
    @Pointcut("@annotation(org.springframework.scheduling.annotation.Scheduled)")
    public void AspectScheduledMethod() {
    }

    @Around(value = "AspectScheduledMethod()")
    public void doScheduleAround(final ProceedingJoinPoint pjp){
        System.out.println("Before doScheduleAround");
        try {
            pjp.proceed();
        } catch (Throwable e) {
            e.printStackTrace();
        } finally {
            System.out.println("After doScheduleAround");
        }
    }

}

上述代码意思是在@Scheduled注解的方法上增加环绕切面,在方法入口打印:Before doScheduleAround以及方法结束前打印:After doScheduleAround

完成以上步骤,我们的测试代码就可以跑起来了。

使用Idea直接启动WebApplication类,需要注意的是这里要在启动命令行中增加-javaagent参数。

然后启动项目,来观察schedule方法执行时输出信息的先后顺序:

最终输出顺序为:

Before doScheduleAround  // AOP前置拦截
In agent transform       // 动态字节码注入代码
In method schedule       // 真实方法体代码
After doScheduleAround   // AOP后置拦截

通过上述结果可以看到顺序为:

  1. 先执行AOP前置代码

  2. 执行Agent代码

  3. 执行真实方法代码

  4. 最后执行AOP后置代码

  5. 后记

最后用个图再来标识下这个过程: