Tenho uma configuração AspectJ com um advice @Around que mede o tempo de execução de um método alvo. No entanto, o tempo de execução está sendo registrado após o advice @AfterReturning, que não é a ordem desejada.
@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);
}
}
Eu esperava que a ordem fosse:
- @Around pré-método (antes da execução de proceed())
- @Antes
- Execução do método de destino (proceed())
- @Around post-method (resposta de tempo de execução)
- @DepoisDeVoltar
- @Depois
Em vez disso, estou recebendo:
- @Around - executado
- @Antes - executado
- Método de destino - executado
- @AfterReturning - executado
- @After - executado
- @Around post-method - executado, mas não na ordem desejada
Saída:
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
O que estou esquecendo aqui? Como posso garantir que o tempo de execução seja registrado antes do aviso @AfterReturning e @After?
Spring Boot 3.3.3. A classe está anotada corretamente com @Aspect e @Component. Além disso, garantiu que @EnableAspectJAutoProxy esteja configurado no aplicativo.
O comportamento que você descreve está documentado no capítulo "Advice Ordering" do manual Spring . Por favor, leia com atenção especial a estas partes:
Ou seja, é de se esperar que
@Around
seja executado primeiro no caminho de entrada e por último no caminho de saída. Sua lógica de aspecto está, portanto, conceitualmente errada. Sugiro que você reduza os conselhos antes/depois para os conselhos ao redor, adicionando alguns try-catch-finally para obter o comportamento desejado. Como alternativa, você pode dividir o aspecto em dois aspectos e certificar-se de usar@Order
a maneira correta para fazer o aspecto de temporização ser executado com uma precedência menor do que o aspecto de registro.