Spring Boot – Performance Logging

Learn to create aspectj based interceptor in spring boot application to write performance logging based on time taken in method executions of aop intercepted methods.

1. Maven Dependency

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

<project xmlns="http://maven.apache.org/POM/4.0.0"
	xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
	<modelVersion>4.0.0</modelVersion>

	<groupId>com.company</groupId>
	<artifactId>SpringBootEhcache</artifactId>
	<version>0.0.1-SNAPSHOT</version>
	<packaging>jar</packaging>

	<name>SpringBootEhcache</name>
	<url>http://maven.apache.org</url>

	<parent>
		<groupId>org.springframework.boot</groupId>
		<artifactId>spring-boot-starter-parent</artifactId>
		<version>2.1.6.RELEASE</version>
		<relativePath />
	</parent>

	<properties>
		<project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
		<project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
		<java.version>1.8</java.version>
		<skipTests>true</skipTests>
	</properties>

	<dependencies>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-web</artifactId>
		</dependency>
		<dependency>
			<groupId>org.springframework.boot</groupId>
			<artifactId>spring-boot-starter-aop</artifactId>
		</dependency>
		<dependency>
			<groupId>org.apache.commons</groupId>
			<artifactId>commons-lang3</artifactId>
		</dependency>
	</dependencies>

	<build>
		<plugins>
			<plugin>
				<groupId>org.springframework.boot</groupId>
				<artifactId>spring-boot-maven-plugin</artifactId>
			</plugin>
		</plugins>
	</build>
</project>

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

<dependency>
	<groupId>org.springframework</groupId>
	<artifactId>spring-aop</artifactId>
	<version>5.0.1.RELEASE</version>
</dependency>
<dependency>
	<groupId>org.aspectj</groupId>
	<artifactId>aspectjweaver</artifactId>
	<version>1.8.12</version>
</dependency>

2. Performance Logging Aspect

Create a spring bean and use annotation @Aspect on class to make it AOP aspect. It will have the methods which can intercept the methods and apply advice around those methods.

Make sure to use @EnableAspectJAutoProxy annotation along with @Configuration to enable aop support, if you are not using spring boot auto configuration.

In given class, we have used @Around advice around all methods present in classes in package com.company.service.

We used StopWatch class to capture start time of method and end time of method. By subtracting start time from end time, we get the total time taken for method execution.

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

At last, we log everything in desired format in log files.

package com.company.aop;

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;
	}
}

3. Classes and intercepted methods

For demo purpose, we are writing a very simple manager class and a single method. AOP will intercept the method and apply advice around the method. The advice is actually measuring the execution time of the method.

package com.company.service;

import java.util.HashMap;

import org.springframework.stereotype.Service;

import com.company.domain.Employee;

@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);
	}
}

package com.company.domain;

import java.io.Serializable;

public class Employee implements Serializable 
{
	private static final long serialVersionUID = 5517244812959569947L;
	
	private Long id;
	private String firstName;
	private String lastName;

	public Employee() {
		super();
	}

	public Employee(Long id, String firstName, String lastName) {
		super();
		this.id = id;
		this.firstName = firstName;
		this.lastName = lastName;
	}

	//Getters and setters

	@Override
	public String toString() {
		return "Employee [id=" + id + ", firstName=" + firstName + ", lastName=" + lastName + "]";
	}
}

4. Spring boot performance logging example

To check the logging, start the spring boot application and access the method.

package com.company;

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, now we are able to measure and log the performance in terms of method execution time for all intercepted methods.

Happy Learning !!