Why does the post-method part of @Around advice appear to execute after @AfterReturning and @After advice?

I have an AspectJ configuration with an @Around advice that measures the execution time of a target method. However, the execution time is being logged after the @AfterReturning advice, which is not the desired order.

@Aspect
@Component
public class LoggingAspectUsingPointcut {

    @Pointcut("execution(* com.sam.aspect.pointcut.controller.UsingPointcutController.*(..))")
    public void controllerMethods() {}

    @Before("controllerMethods()")
    public void logBefore() {
        System.out.println("Method is about to be called");
    }

    @Around("controllerMethods()")
    public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
        System.out.println("Around advice start");
        long start = System.currentTimeMillis();
        Object proceed = joinPoint.proceed(); // Proceed with the method execution
        long executionTime = System.currentTimeMillis() - start;
        System.out.println(joinPoint.getSignature() + " executed in " + executionTime + "ms");
        System.out.println("Around Advice End");
        return proceed;
    }

    @After("controllerMethods()")
    public void logAfter() {
        System.out.println("Method has been called");
    }

    @AfterReturning(pointcut = "execution(* com.sam.aspect.pointcut.controller.UsingPointcutController  .*(..))", returning = "result")
    public void logAfterReturning(Object result) {
        System.out.println("Method executed successfully." + result);
    }
}

I expected the order to be:

@Around pre-method(before execution of proceed())
@Before
Target method execution(proceed())
@Around post-method (execution time response)
@AfterReturning
@After

Instead, I'm getting:

@Around - executed
@Before - executed
Target method - executed
@AfterReturning - executed
@After - executed
@Around post-method - executed but not in desired order

Output:

Around advice start
Method is about to be called
Method executed successfully.[Record 1, Record 2, Record 3, Record 4, Record 5, Record 6, Record 7, Record 8, Record 9, Record 10]
Method has been called
List com.sam.aspect.pointcut.controller.UsingPointcutController.getData() executed in 13ms
Around Advice End

What am I missing here? How can I ensure that the execution time is logged before the @AfterReturning and @After advice?

Spring Boot 3.3.3. Class is properly annotated with @Aspect and @Component. Also, ensured that @EnableAspectJAutoProxy is configured in the application.

Solution

The behaviour you describe is documented in the Spring manual chapter "Advice Ordering". Please read it with special attention to these parts:

What happens when multiple pieces of advice all want to run at the same join point? Spring AOP follows the same precedence rules as AspectJ to determine the order of advice execution. The highest precedence advice runs first "on the way in" (so, given two pieces of before advice, the one with highest precedence runs first). "On the way out" from a join point, the highest precedence advice runs last (so, given two pieces of after advice, the one with the highest precedence will run second).

(...)

As of Spring Framework 5.2.7, advice methods defined in the same @Aspect class that need to run at the same join point are assigned precedence based on their advice type in the following order, from highest to lowest precedence: @Around, @Before, @After, @AfterReturning, @AfterThrowing. Note, however, that an @After advice method will effectively be invoked after any @AfterReturning or @AfterThrowing advice methods in the same aspect, following AspectJ’s "after finally advice" semantics for @After.

I.e., it is to be expected that @Around runs first on the way in and last on the way out. Your aspect logic is therefore conceptually wrong. I suggest to collapse the before/after advices into the around advice, adding some try-catch-finally to get the behaviour you want. Alternatively, you could split the aspect into two aspects and make sure to use @Order the right way to make the timing aspect run with a lower precedence than the logging aspect.