sping AOP切面注解使用中的坑–同一个类中嵌套方法注解不生效
在开发过程中,监控方法运行时间,然后获取程序运行的瓶颈,是一个常见的优化步骤。写一个spring切面实现的注解来实现函数运行时间的监控看上去是一个比较直接的解决方案。
使用spring AOP实现方法运行时间的日志打印,其实比较简单:
首先定义一个注解:
//com.TimeLog
@Target({ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
public @interface TimeLog {
}
然后实现该注解的切面:
//com.TimeLogAspect
@Aspect
@Component
public class TimeLogAspect {
@Pointcut("@annotation(com.TimeLog)")
public void handlingTimePointcut() {}
//定义一个环绕切面
@Around("handlingTimePointcut()")
public Object handlingTimeAround(ProceedingJoinPoint joinPoint){
try {
long start = System.currentTimeMillis();
Object proceed = joinPoint.proceed();
System.out.println(proceed);
//打印方法执行时间
System.out.println("方法执行时间:" + (System.currentTimeMillis() - start));
return proceed;
} catch (Throwable throwable) {
throwable.printStackTrace();
}
return null;
}
}
在确保这个切面的bean被注入之后,可以使用@TimeLog注解在函数上,如:
class Test{
@TimeLog
void test(){
for(int i=0; i < 20000; ++i)
Symtem.out.println(i);
}
}
//输出结果:方法执行时间:121
看似问题已经完美解决,但是其实由于spring AOP的内部实现原因,会存在一个bug。
如:
class Test{
@TimeLog
void test(){
for(int i=0; i < 20000; ++i)
Symtem.out.println(i);
test2();
}
@TimeLog
void test2(){
}
}
在test中调用test2并不会输出test2的运行时间,即使test2也被@TimeLog修饰。为什么会这样呢?简单解释是这样的:
spring AOP的内部实现是对Test类进行了代理,如:
clase TestProxy {
private Test test;
...
public test(){
doBefore();
test.test(); // 1
doAfter();
}
public test2() {
doBefore();
test.test2();
doAfter();
}
public doBefore() {
//切面逻辑。代理会在被注解的方法调用开始前调用这个方法,
//执行切面逻辑
}
public doAfter() {
//切面逻辑。代理会在被注解的方法调用结束后调用这个方法,
//执行切面逻辑
}
}
主要的问题出在标注1处,在执行test.test()时,内部直接调用test.test2(),而不是重新生成新代理执行代理的test2()。
由于直接调用this.test2(),而不是代理的test2方法,所以doBefore()和doAfter()都不能不执行,注解的切面就不会生效。
那么,如何才能写一个打印合理的方法运行时间的注解呢?可以参考bytebuddy解决spring AOP切面同一个类嵌套方法不生效问题