AspectJ切面执行两次原因分析

背景
转眼之间，发现博客已经将近半年没更新了，甚是惭愧。话不多说，正如标题所言，最近在使用AspectJ的时候，发现拦截器（AOP切面）执行了两次了。我们知道，AspectJ是AOP的一种解决方案，本质上是通过代理类在目标方法执行通知（Advice），然后由代理类再去调用目标方法。所以，从这点讲，拦截器应该只会执行一次。但是在测试的时候发现拦截器执行了两次。

问题重现
既然问题已经明了，那么可以通过代码简单重现这个问题，从而更深层次分析到底是什么原因导致的。

定义一个注解：

package com.rhwayfun.aspect;import java.lang.annotation.*;@Target({ElementType.METHOD})@Retention(RetentionPolicy.CLASS)@Documentedpublic @interface StatsService {}
1
2
3
4
5
6
7
8
9

为该注解定义切面：

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;@Aspectpublic 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.");        }    }}
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

方法测试：

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());    }}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21

输出结果：

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);    }}
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

请注意两个连接点：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)")。

重新运行上面的测试类，结果如下：