Spring Boot – AOP Demo – Create Annotation to log time taken for method Execution.

In this short tutorial we are going to create an annotation to log the method execution time. We are going to use Spring AOP (Aspect Oriented Programming) with Spring Boot for this tutorial. Aspect Oriented Programming is a powerful concept to address cross cutting concerns like transaction management, execution time logging etc.

Lets say we have a spring boot rest api and we need to find the response time for the methods. Instead of writing the time measurement logic in all the methods, we can separate that aspect and use an annotation to invoke it.

Code to create annotation.

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Timed {
}

Code to create the aspect. Here @Aspect annotation marks this class as an Aspect. @Component is needed for the Spring Boot to scan this Aspect. Then we are using the @Around advice so that we can take the currentTime in millis before the method and after the method execution (pjp.proceed()) and then the log the difference. Return the result of pjp.proceed() as an Object. This aspect specifies all the methods annotated with @Timed should be timed and the time taken should be logged.

@Aspect
@Component
@Slf4j
public class AroundTimedAspect {
    @Around("@annotation(com.example.demo.annotation.Timed)")
    public Object doProfile(ProceedingJoinPoint pjp) throws Throwable{
        Object result;
        long startTime = System.currentTimeMillis();
        try {
            result = pjp.proceed();
        }finally {
            long endTime = System.currentTimeMillis();
            log.info("The method : {} took {} ms", pjp.getSignature(), (endTime - startTime));
        }
        return result;
    }
}

Then we annotate the methods to log.

@Timed
public String sayHello(){
    return "Hello !! How are you ? ".concat(HelloService.offerHelp());
}

@Timed
public static String offerHelp(){
    return "How can i help you ? " + System.currentTimeMillis();
}

The only dependency needed for spring boot would be spring-boot-starter-aop. This implicitly brings in org.springframework:spring-aop and org.aspectj:aspectjweaver.

<dependency>
   <groupId>org.springframework.boot</groupId>
   <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

When we run the Spring batch application and call the localhost:8080/hello endpoint, the below line will be logged.

The method : String com.example.demo.service.HelloService.sayHello() took 22 ms

But wait. Where is the log statement for offerHelp method ? It is not logged because it is an internal call within the same object and it is a static method. Springs AOP framework is proxy based. Hence only public methods on a Bean will be intercepted. If we want to intercept private / protected / static methods / constructors / calls within an object we should use the very powerful native AspectJ weaving.

The full code for this tutorial is available in github.