Spring Performace Logging with Method Execution Time

Learn to create aspectj-based Interceptor for logging the method execution time in a Spring boot application. This is helpful for adding performance logging in Spring applications using Spring AOP.

1. Maven

To add AOP support, we must include spring-boot-starter-aop dependency in the application.

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

If you are not using Spring boot, then add the below dependencies.

<dependency>
  <groupId>org.springframework</groupId>
  <artifactId>spring-aop</artifactId>
  <version>${spring.aop.version}</version>
</dependency>
<dependency>
  <groupId>org.aspectj</groupId>
  <artifactId>aspectjweaver</artifactId>
  <version>${aspectjweaver.version}</version>
</dependency>

2. AOP Aspect to Capture Method Execution Time

Create a spring bean and use annotation @Aspect to make it an AOP aspect. It will have methods that can intercept the currently executing methods and apply the performance advice around those methods.

Make sure to use @EnableAspectJAutoProxy annotation along with @Configuration to enable AOP support, if we are not using spring boot autoconfiguration.

In the following example, we have used @Around advice around all methods present in classes in the package com.company.service. We used StopWatch class to capture the method’s start and end times. By subtracting the start time from the end time, we get the total time taken for method execution.

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.springframework.stereotype.Component;
import org.springframework.util.StopWatch;

@Aspect
@Component
public class LoggingAspect
{
	private static final Logger LOGGER = LogManager.getLogger(LoggingAspect.class);

	//AOP expression for which methods shall be intercepted
	@Around("execution(* com.company.service..*(..)))")
	public Object profileAllMethods(ProceedingJoinPoint proceedingJoinPoint) throws Throwable
	{
		MethodSignature methodSignature = (MethodSignature) proceedingJoinPoint.getSignature();

		//Get intercepted method details
		String className = methodSignature.getDeclaringType().getSimpleName();
		String methodName = methodSignature.getName();

		final StopWatch stopWatch = new StopWatch();

		//Measure method execution time
		stopWatch.start();
		Object result = proceedingJoinPoint.proceed();
		stopWatch.stop();

		//Log method execution time
		LOGGER.info("Execution time of " + className + "." + methodName + " :: " + stopWatch.getTotalTimeMillis() + " ms");

		return result;
	}
}

The ProceedingJoinPoint class argument provides us the class name and method name which is going to be executed.

3. Spring Performance Logging Example

We are writing a simple manager class and a single method for demo purposes. AOP will intercept the method and apply advice around the method. The advice is actually measuring the execution time of the method.

@Service
public class EmployeeManager 
{
  static HashMap<Long, Employee> db = new HashMap<>();
   
  static {
    db.put(1L, new Employee(1L, "Alex", "Gussin"));
    db.put(2L, new Employee(2L, "Brian", "Schultz"));
  }
   
  public Employee getEmployeeById(Long id) {
    return db.get(id);
  }
}

Start the spring boot application and access the method to check the logging.

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.CommandLineRunner;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.ApplicationContext;
import org.springframework.context.annotation.Bean;

import com.company.service.EmployeeManager;

@SpringBootApplication
public class Application {

	@Autowired
	private EmployeeManager employeeManager;

	public static void main(String[] args) {
		SpringApplication.run(Application.class, args);
	}

	@Bean
	public CommandLineRunner commandLineRunner(ApplicationContext ctx) {
		return args -> {

			System.out.println(employeeManager.getEmployeeById(1L));

		};
	}
}

Program output.

16:29:25.031 [main] INFO  com.company.aop.LoggingAspect - Execution time of EmployeeManager.getEmployeeById :: 9 ms
 
Employee [id=1, firstName=Alex, lastName=Gussin]

Clearly, we can now measure and log the performance in terms of method execution time for all intercepted methods in Spring.

Happy Learning !!