Interviewer: what is the execution order of Spring annotation @ After,@Around,@Before?

Keywords: Java

There are @ Before, @ After, @ Around, @ AfterRunning annotations in AOP.

First up and down their own code, defined the definition of tangent point

@Aspect
@Component
public class LogApsect {
 
    private static final Logger logger = LoggerFactory.getLogger(LogApsect.class);
 
    ThreadLocal<Long> startTime = new ThreadLocal<>();
 
    // The first * represents unlimited return types
    // The second * represents all classes
    // The third * represents all methods
    // (..) represents unlimited parameters
    @Pointcut("execution(public * com.lmx.blog.controller.*.*(..))")
    @Order(2)
    public void pointCut(){};
 
    @Pointcut("@annotation(com.lmx.blog.annotation.RedisCache)")
    @Order(1) // Order represents priority. The smaller the number, the higher the priority
    public void annoationPoint(){};
 
    @Before(value = "annoationPoint() || pointCut()")
    public void before(JoinPoint joinPoint){
        System.out.println("Execute before method execution......before");
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();
        logger.info("<=====================================================");
        logger.info("Request source: =>" + request.getRemoteAddr());
        logger.info("request URL: " + request.getRequestURL().toString());
        logger.info("Request method:" + request.getMethod());
        logger.info("Response method:" + joinPoint.getSignature().getDeclaringTypeName() + "." + joinPoint.getSignature().getName());
        logger.info("Request parameters:" + Arrays.toString(joinPoint.getArgs()));
        logger.info("------------------------------------------------------");
        startTime.set(System.currentTimeMillis());
    }
 
    // Define the tangent expression that needs to be matched and the matching parameters
    @Around("pointCut() && args(arg)")
    public Response around(ProceedingJoinPoint pjp,String arg) throws Throwable{
        System.out.println("name:" + arg);
        System.out.println("Method surround start...around");
        String result = null;
        try{
            result = pjp.proceed().toString() + "aop String";
            System.out.println(result);
        }catch (Throwable e){
            e.printStackTrace();
        }
        System.out.println("Method surround end...around");
        return (Response) pjp.proceed();
    }
 
    @After("within(com.lmx.blog.controller.*Controller)")
    public void after(){
        System.out.println("Method...after.");
    }
 
    @AfterReturning(pointcut="pointCut()",returning = "rst")
    public void afterRunning(Response rst){
        if(startTime.get() == null){
            startTime.set(System.currentTimeMillis());
        }
        System.out.println("Method execution completed...afterRunning");
        logger.info("Elapsed time (MS):" +  (System.currentTimeMillis() - startTime.get()));
        logger.info("Return data:{}", rst);
        logger.info("==========================================>");
    }
 
    @AfterThrowing("within(com.lmx.blog.controller.*Controller)")
    public void afterThrowing(){
        System.out.println("After the exception occurs...afterThrowing");
    }
 
 
}

Recommend a basic Spring Boot tutorial and practical example:
https://github.com/javastacks...

@Before, @ After, @ Around annotation differences, you can baidu. In short, @ Around can implement the functions of @ before and @ After in one method.

First, let's test a method to get a record in the database

@RequestMapping("/achieve")
public Response achieve(){
    System.out.println("Method execution-----------");
    return Response.ok(articleDetailSercice.getPrimaryKeyById(1L));
}

The following is the log printed by the console

Execute before method execution......before
2018-11-23 16:31:59.795 [http-nio-8888-exec-9] INFO  c.l.blog.config.LogApsect - <=====================================================
2018-11-23 16:31:59.795 [http-nio-8888-exec-9] INFO  c.l.blog.config.LogApsect - Request source: =>0:0:0:0:0:0:0:1
2018-11-23 16:31:59.795 [http-nio-8888-exec-9] INFO  c.l.blog.config.LogApsect - request URL: http://localhost:8888/user/achieve
2018-11-23 16:31:59.795 [http-nio-8888-exec-9] INFO  c.l.blog.config.LogApsect - Request method: GET
2018-11-23 16:31:59.795 [http-nio-8888-exec-9] INFO  c.l.blog.config.LogApsect - Response method: com.lmx.blog.controller.UserController.achieve
2018-11-23 16:31:59.796 [http-nio-8888-exec-9] INFO  c.l.blog.config.LogApsect - Request parameters:[]
2018-11-23 16:31:59.796 [http-nio-8888-exec-9] INFO  c.l.blog.config.LogApsect - ------------------------------------------------------
Method execution-----------
2018-11-23 16:31:59.806 [http-nio-8888-exec-9] DEBUG c.l.b.m.A.selectPrimaryKey - ==>  Preparing: select * from article_detail where id = ? 
2018-11-23 16:31:59.806 [http-nio-8888-exec-9] DEBUG c.l.b.m.A.selectPrimaryKey - ==>  Preparing: select * from article_detail where id = ? 
2018-11-23 16:31:59.806 [http-nio-8888-exec-9] DEBUG c.l.b.m.A.selectPrimaryKey - ==> Parameters: 1(Long)
2018-11-23 16:31:59.806 [http-nio-8888-exec-9] DEBUG c.l.b.m.A.selectPrimaryKey - ==> Parameters: 1(Long)
2018-11-23 16:31:59.814 [http-nio-8888-exec-9] DEBUG c.l.b.m.A.selectPrimaryKey - <==      Total: 1
2018-11-23 16:31:59.814 [http-nio-8888-exec-9] DEBUG c.l.b.m.A.selectPrimaryKey - <==      Total: 1
 Method...after.
Method execution completed...afterRunning
2018-11-23 16:31:59.824 [http-nio-8888-exec-9] INFO  c.l.blog.config.LogApsect - Elapsed time (MS): 27
2018-11-23 16:31:59.824 [http-nio-8888-exec-9] INFO  c.l.blog.config.LogApsect - Return data: com.lmx.blog.common.Response@8675ce5
2018-11-23 16:31:59.824 [http-nio-8888-exec-9] INFO  c.l.blog.config.LogApsect - ==========================================>

As you can see, because there is no rule matching @ Around, there is no surround notification. (PS: the surround notification I defined means that it must conform to the methods under the controller package, and the methods must have parameters, but the above methods have no parameters, so only the @ before and @ after methods are used, which does not conform to the matching logic of @ Around.)

Let's try another method with parameters

@RedisCache(type = Response.class)
@RequestMapping("/sendEmail")
public Response sendEmailToAuthor(String content){
    System.out.println("Test execution times");
    return Response.ok(true);
}

The following is the console print of this part of the code

name:What about the second email
 Method surround start...around
 Execute before method execution......before
2018-11-23 16:34:55.347 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - <=====================================================
2018-11-23 16:34:55.347 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - Request source: =>0:0:0:0:0:0:0:1
2018-11-23 16:34:55.347 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - request URL: http://localhost:8888/user/sendEmail
2018-11-23 16:34:55.348 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - Request method: GET
2018-11-23 16:34:55.348 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - Response method: com.lmx.blog.controller.UserController.sendEmailToAuthor
2018-11-23 16:34:55.348 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - Request parameters:[What about the second email]
2018-11-23 16:34:55.348 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - ------------------------------------------------------
Test execution times
com.lmx.blog.common.Response@6d17f2fdaop String
 Method surround end...around
 Execute before method execution......before
2018-11-23 16:34:55.349 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - <=====================================================
2018-11-23 16:34:55.349 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - Request source: =>0:0:0:0:0:0:0:1
2018-11-23 16:34:55.349 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - request URL: http://localhost:8888/user/sendEmail
2018-11-23 16:34:55.349 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - Request method: GET
2018-11-23 16:34:55.349 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - Response method: com.lmx.blog.controller.UserController.sendEmailToAuthor
2018-11-23 16:34:55.349 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - Request parameters:[What about the second email]
2018-11-23 16:34:55.350 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - ------------------------------------------------------
Test execution times
 Method...after.
Method execution completed...afterRunning
2018-11-23 16:34:55.350 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - Elapsed time (MS): 0
2018-11-23 16:34:55.350 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - Return data: com.lmx.blog.common.Response@79f85428
2018-11-23 16:34:55.350 [http-nio-8888-exec-2] INFO  c.l.blog.config.LogApsect - ==========================================>

Obviously, this method complies with the matching rule of @ Around notification, so it enters the logic of @ Around, but a problem is found. All methods are executed twice, whether in the aspect layer or the method layer. (someone might ask me if I didn't use the custom annotation @ RedisCache(type = Response.class). Why does it comply with the matching rule of @ Around, which will be described below)

By analyzing the printing order of the log, we can conclude that when the surround method is executed, the method under @ Around will be given priority@ Paste the code again in the Around method.

// Define the tangent expression that needs to be matched and the matching parameters
@Around("pointCut() && args(arg)")
public Response around(ProceedingJoinPoint pjp,String arg) throws Throwable{
    System.out.println("name:" + arg);
    System.out.println("Method surround start...around");
    String result = null;
    try{
        result = pjp.proceed().toString() + "aop String";
        System.out.println(result);
    }catch (Throwable e){
        e.printStackTrace();
    }
    System.out.println("Method surround end...around");
    return (Response) pjp.proceed();
}

After printing the first two lines of code, the @ before method is executed instead because the proceedingjoinpoint. Processed () method is triggered halfway. This method is used to execute the proxy method, that is, after executing this method, we will execute our controller method, then execute @ before, @ after, then return to @ Around to execute the unexecuted method, and finally execute @ afterRunning. If an exception is thrown, we can execute @ AfterThrowing

In other words, the execution sequence of surround is @ Around → @ Before → @ After → @ Around → @ afterrunning (if there is an exception → @ AfterThrowing)

The above log is equivalent to executing the above results twice. The root cause is the method of proceedingjoinpoint. Processed(). It can be found that we use this method twice in the @ Around method. However, each time we call this method, we will go through the operation After @ Before → @ After → @ Around to execute proceedingjoinpoint. Processed() → @ afterrunning (if there is an exception → @ AfterThrowing). Therefore, the problem occurs here. So change the code in the @ Around section to solve the problem. The changed code is as follows:

@Around("pointCut() && args(arg)")
public Response around(ProceedingJoinPoint pjp,String arg) throws Throwable{
    System.out.println("name:" + arg);
    System.out.println("Method surround start...around");
    String result = null;
    Object object = pjp.proceed();
    try{
        result = object.toString() + "aop String";
        System.out.println(result);
    }catch (Throwable e){
        e.printStackTrace();
    }
    System.out.println("Method surround end...around");
    return (Response) object;
}

Run results after code changes

name:What about the second email
 Method surround start...around
 Execute before method execution......before
2018-11-23 16:52:14.315 [http-nio-8888-exec-4] INFO  c.l.blog.config.LogApsect - <=====================================================
2018-11-23 16:52:14.315 [http-nio-8888-exec-4] INFO  c.l.blog.config.LogApsect - Request source: =>0:0:0:0:0:0:0:1
2018-11-23 16:52:14.315 [http-nio-8888-exec-4] INFO  c.l.blog.config.LogApsect - request URL: http://localhost:8888/user/sendEmail
2018-11-23 16:52:14.315 [http-nio-8888-exec-4] INFO  c.l.blog.config.LogApsect - Request method: GET
2018-11-23 16:52:14.316 [http-nio-8888-exec-4] INFO  c.l.blog.config.LogApsect - Response method: com.lmx.blog.controller.UserController.sendEmailToAuthor
2018-11-23 16:52:14.316 [http-nio-8888-exec-4] INFO  c.l.blog.config.LogApsect - Request parameters:[What about the second email]
2018-11-23 16:52:14.316 [http-nio-8888-exec-4] INFO  c.l.blog.config.LogApsect - ------------------------------------------------------
Test execution times
com.lmx.blog.common.Response@1b1c76afaop String
 Method surround end...around
 Method...after.
Method execution completed...afterRunning
2018-11-23 16:52:14.316 [http-nio-8888-exec-4] INFO  c.l.blog.config.LogApsect - Elapsed time (MS): 0
2018-11-23 16:52:14.316 [http-nio-8888-exec-4] INFO  c.l.blog.config.LogApsect - Return data: com.lmx.blog.common.Response@1b1c76af
2018-11-23 16:52:14.316 [http-nio-8888-exec-4] INFO  c.l.blog.config.LogApsect - ==========================================>

Back to the above unsolved problem, why can I enter the @ Around method when I define another annotation of the section?

Because our method is still under the controller, it meets this requirement. It is only useful if we define a controller under the controller package. For example:

@Pointcut("execution(public * com.lmx.blog.controller.UserController.*(..))")

If the method we just defined is written under the TestController, it does not comply with the matching rules of the @ Around method or the annotation rules of @ before and @ after. Therefore, it will not match any rule. If you need to match a specific method, you can use the custom annotation form or the method under the feature controller

① : annotation form of properties

@Pointcut("@annotation(com.lmx.blog.annotation.RedisCache)")
@Order(1) // Order represents priority. The smaller the number, the higher the priority
public void annoationPoint(){};

Then add @ RedisCache annotation on the required method, and add the method name of the tangent point ("annotationpoint()") on @ Before, @ After, @ Around and other methods. If there are multiple annotations to match, separate them with |

② : specify the controller or the method under the controller

@Pointcut("execution(public * com.lmx.blog.controller.UserController.*(..))")
@Order(2)
public void pointCut(){};

This part of the code specifies all methods under UserController under com.lmx.blog.controller package.

The first * represents unlimited return types

The second * represents all methods under the controller, (..) represents unlimited parameters

summary

When the method conforms to the pointcut rule and does not conform to the rule of surround notification, the execution sequence is as follows

@Before → @ After → @ afterrunning (if there is an exception → @ AfterThrowing)

When the method complies with the pointcut rule and the rules surrounding the notification, the order of execution is as follows

@Around → @ Before → @ around → @ After → @ After → @ afterrunning (if abnormal → @ AfterThrowing)

Original link: https://blog.csdn.net/lmx1252...

Copyright notice: This is the original article of CSDN blogger "Leonis, L", which follows the CC 4.0 BY-SA copyright agreement. Please attach the original source link and this notice for reprint.

Recent hot article recommendations:

1.1000 + Java interview questions and answers (2021 latest version)

2.Stop playing if/ else on the full screen. Try the strategy mode. It's really fragrant!!

3.What is the new syntax of xx ≠ null in Java?

4.Spring Boot 2.5 heavy release, dark mode is too explosive!

5.Java development manual (Songshan version) is the latest release. Download it quickly!

Feel good, don't forget to like + forward!

Posted by ricerocket on Thu, 11 Nov 2021 02:28:32 -0800