Spring Boot: Measure Execution Time using Spring AOP and AspectJ

Photo by Veri Ivanova on Unsplash

In this post, I like to document the steps followed to solve the Concern surrounding logging execution time in a Spring Boot Application using Spring-AOP(Aspect Oriented Programming) and AspectJ.

GitHub: https://github.com/shinemon/demo-spring-boot/tree/master/spring-boot-aop-aspectj

Let’s consider a simple Spring Boot Application with a Controller and Service.

Controller:

@RestController
@Slf4j
@RequestMapping("/api")
public class Employee {

    @Autowired
    private EmployeeService employeeService;

    @GetMapping(value = "/get/employee/name/{id}")
    public String getEmployeeName(@PathVariable String id){
        if (StringUtils.isBlank(id)){
            return null;
        }
        return employeeService.getEmployeeNameFromId(id);
    }
}

Service:

@Service
@Slf4j
public class EmployeeService {

    public String getEmployeeNameFromId(String id){
        return "Test Name From Service";
    }
}

Aim: Calculate and Log execution time taken by a Method.

Solution (Traditional Me😀 ): find current time in milliseconds prior to method start, and subtract with current time post method execution. May be create a Util, and still we will end up several boiler plater code within our class/methods.

Better Solution:

Spring-AOP & AspectJ: Will help us to modularize our current logging Execution Time taken concern.

There are different Advice per AOP Concepts like Before, After, Around. Here we will make use of Around Advice, which helps to surround a Method Execution (Joint Point — term per AOP i.e. a point during the execution of a program.)

Create: ExecutionTimeAdvice and Around with custom Annotation (say TrackExecutionTime)

ExecutionTimeAdvice:

@Aspect
@Component
@Slf4j
@ConditionalOnExpression("${aspect.enabled:true}")
public class ExecutionTimeAdvice {

    @Around("@annotation(com.mailshine.springboot.aop.aspectj.advise.TrackExecutionTime)")
    public Object executionTime(ProceedingJoinPoint point) throws Throwable {
        long startTime = System.currentTimeMillis();
        Object object = point.proceed();
        long endtime = System.currentTimeMillis();
        log.info("Class Name: "+ point.getSignature().getDeclaringTypeName() +". Method Name: "+ point.getSignature().getName() + ". Time taken for Execution is : " + (endtime-startTime) +"ms");
        return object;
    }
}

TrackExecutionTime:

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

Now you only need to add “@TrackExecutionTime” annotation to your desired Methods in any of your class.

Adding to our Controller & Service:

@RestController
@Slf4j
@RequestMapping("/api")
public class Employee {

    @Autowired
    private EmployeeService employeeService;

    @GetMapping(value = "/get/employee/name/{id}")
    @TrackExecutionTime
    public String getEmployeeName(@PathVariable String id){
        if (StringUtils.isBlank(id)){
            return null;
        }
        return employeeService.getEmployeeNameFromId(id);
    }
}

@Service
@Slf4j
public class EmployeeService {

    @TrackExecutionTime
    public String getEmployeeNameFromId(String id){
        return "Test Name From Service";
    }
}

Log:

INFO 1069 — — [nio-8080-exec-4] c.m.s.a.a.advise.ExecutionTimeAdvice : Class Name: EmployeeService. Method Name: getEmployeeNameFromId. Time taken for Execution is : 5ms
INFO 1069 — — [nio-8080-exec-4] c.m.s.a.a.advise.ExecutionTimeAdvice : Class Name: Employee. Method Name: getEmployeeName. Time taken for Execution is : 23ms

This shows a simple example of measuring and logging Method Execution Time in a Spring Boot application using AOP and AspectJ.

shinemon/demo-spring-boot

🙏