AspectJ切面執行兩次原因分析
背景
轉眼之間,發現部落格已經將近半年沒更新了,甚是慚愧。話不多說,正如標題所言,最近在使用AspectJ的時候,發現攔截器(AOP切面)執行了兩次了。我們知道,AspectJ是AOP的一種解決方案,本質上是通過代理類在目標方法執行通知(Advice),然後由代理類再去呼叫目標方法。所以,從這點講,攔截器應該只會執行一次。但是在測試的時候發現攔截器執行了兩次。
問題重現
既然問題已經明瞭,那麼可以通過程式碼簡單重現這個問題,從而更深層次分析到底是什麼原因導致的。
定義一個註解:
package com.rhwayfun.aspect;
import java.lang.annotation.*;
@Target ({ElementType.METHOD})
@Retention(RetentionPolicy.CLASS)
@Documented
public @interface StatsService {
}
為該註解定義切面:
package com.rhwayfun.aspect;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@Aspect
public class StatsServiceInterceptor {
private static Logger log = LoggerFactory.getLogger(StatsServiceInterceptor.class);
@Around("@annotation(StatsService)")
public Object invoke(ProceedingJoinPoint pjp) {
try {
log.info("before invoke target." );
return pjp.proceed();
} catch (Throwable e) {
log.error("invoke occurs error:", e);
return null;
} finally {
log.info("after invoke target.");
}
}
}
方法測試:
package com.rhwayfun;
import com.rhwayfun.aspect.StatsService;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.time.LocalDateTime;
public class AspectTest {
private static Logger log = LoggerFactory.getLogger(AspectTest.class);
public static void main(String[] args) {
AspectTest.print();
}
@StatsService
public static void print(){
log.info("Now: {}", LocalDateTime.now());
}
}
輸出結果:
debug分析
由於是靜態織入,所以可以通過反編譯工具檢視編譯後的檔案,如下:
public class AspectTest
{
private static Logger log;
private static final /* synthetic */ JoinPoint$StaticPart ajc$tjp_0;
private static final /* synthetic */ JoinPoint$StaticPart ajc$tjp_1;
public static void main(final String[] args) {
StatsServiceInterceptor.aspectOf().invoke(((AroundClosure)new AspectTest$AjcClosure1(new Object[] { Factory.makeJP(AspectTest.ajc$tjp_0, (Object)null, (Object)null) })).linkClosureAndJoinPoint(0));
}
@StatsService
public static void print() {
StatsServiceInterceptor.aspectOf().invoke(((AroundClosure)new AspectTest$AjcClosure3(new Object[] { Factory.makeJP(AspectTest.ajc$tjp_1, (Object)null, (Object)null) })).linkClosureAndJoinPoint(65536));
}
static {
ajc$preClinit();
AspectTest.log = LoggerFactory.getLogger((Class)AspectTest.class);
}
private static /* synthetic */ void ajc$preClinit() {
final Factory factory = new Factory("AspectTest.java", (Class)AspectTest.class);
ajc$tjp_0 = factory.makeSJP("method-call", (Signature)factory.makeMethodSig("9", "print", "com.rhwayfun.AspectTest", "", "", "", "void"), 17);
ajc$tjp_1 = factory.makeSJP("method-execution", (Signature)factory.makeMethodSig("9", "print", "com.rhwayfun.AspectTest", "", "", "", "void"), 22);
}
}
請注意兩個連線點:ajc$tjp_0
和ajc$tjp_1
,這兩個連線點是產生兩次呼叫的關鍵,問題註解明明是加上print()
方法上的,為什麼main()
方法也被注入了通知呢?正因為main()
方法也織入了通知,所以就形成了A call B, B call print()
的呼叫鏈,有兩次method-call
,一次method-execution
,method-execution
才是我們的目標方法print()
,所以我們才看到了兩次輸出。
method-call
和method-execution
都是連線點ProceedingJoinPoint
的kind
屬性
其實,這屬於Ajc編譯器的一個Bug,詳見Ajc-bug
所以,到這一步,問題就很清晰了,因為Ajc編輯器的bug,導致了在main
方法中也織入了通知,所以在執行的時候,輸出了兩次日誌。
- 解決方法
-
方案一
因為兩次呼叫的kind屬性不一樣,所以可以通過kind屬性來判斷時候呼叫切面。這樣顯得不優雅,而且如果切面有更多的邏輯的話,需要加各種if-else的判斷,所以不推薦。 -
方法二
更優雅的方案是修改@Around("@annotation(StatsService)")的邏輯
,改為@Around("execution(* *(..)) && @annotation(StatsService)")
。
重新執行上面的測試類,結果如下: