- 问题描述:
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 时间是否包含拦截器自身的执行时间呢?
这似乎是一个触及灵魂的问题!
- 问题分析
要弄清楚这个问题,我们就要回到上述Self 方法统计的本质。
我们知道Pinpoint是通过字节码技术动态对方法的进行修改的,也就是说本质上也是给方法体添加了拦截器来统计方法执行时间的。所以上述问题本质上是AOP动态代理和字节码注入(代理)的执行先后顺序问题。
说到这里有经验的同学可能一下子就知道答案了,Self = t11 - t2 - t3。原因是字节码技术是更底层的技术,他作用在class上,而AOP只是一种动态代理技术,他作用在容器或框架上。
确实是这样的,为了验证以上结果,我们拿实际代码测试一下看看(因为Pinpoint太过臃肿,我们自己实现个简答的javaagent来模拟下Pinpoint的方法注入)。
- 编写动态字节码注入代码
首先来写一段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就可以使用了。
- 编写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后置拦截
通过上述结果可以看到顺序为:
-
先执行AOP前置代码
-
执行Agent代码
-
执行真实方法代码
-
最后执行AOP后置代码
-
后记
最后用个图再来标识下这个过程: