Spring Performance Logging

1. Overview

In this tutorial, we’ll look into a couple of basic options the Spring Framework offers for performance monitoring.

2. PerformanceMonitorInterceptor

A simple solution to get basic monitoring functionality for the execution time of our methods, we can make use of the PerformanceMonitorInterceptor class out of Spring AOP (Aspect Oriented Programming).

Spring AOP allows the defining of cross-cutting concerns in applications, meaning code that intercepts the execution of one or more methods, in order to add extra functionality.

The PerformanceMonitorInterceptor class is an interceptor that can be associated with any custom method to be executed at the same time. This class uses a StopWatch instance to determine the beginning and ending time of the method run.

Let’s create a simple Person class and a PersonService class with two methods that we will monitor:

public class Person {
    private String lastName;
    private String firstName;
    private LocalDate dateOfBirth;

    // standard constructors, getters, setters
}

public class PersonService {
    
    public String getFullName(Person person){
        return person.getLastName()+" "+person.getFirstName();
    }
    
    public int getAge(Person person){
        Period p = Period.between(person.getDateOfBirth(), LocalDate.now());
        return p.getYears();
    }
}

In order to make use of the Spring monitoring interceptor, we need to define a pointcut and advisor:

@Configuration
@EnableAspectJAutoProxy
@Aspect
public class AopConfiguration {
    
    @Pointcut(
      "execution(public String com.baeldung.performancemonitor.PersonService.getFullName(..))"
    )
    public void monitor() { }
    
    @Bean
    public PerformanceMonitorInterceptor performanceMonitorInterceptor() {
        return new PerformanceMonitorInterceptor(true);
    }

    @Bean
    public Advisor performanceMonitorAdvisor() {
        AspectJExpressionPointcut pointcut = new AspectJExpressionPointcut();
        pointcut.setExpression("com.baeldung.performancemonitor.AopConfiguration.monitor()");
        return new DefaultPointcutAdvisor(pointcut, performanceMonitorInterceptor());
    }
    
    @Bean
    public Person person(){
        return new Person("John","Smith", LocalDate.of(1980, Month.JANUARY, 12));
    }
 
    @Bean
    public PersonService personService(){
        return new PersonService();
    }
}

The pointcut contains an expression that identifies the methods that we want to be intercepted — in our case the getFullName() method of the PersonService class.

After configuring the performanceMonitorInterceptor() bean, we need to associate the interceptor with the pointcut. This is achieved through an advisor, as shown in the example above.

Finally, the @EnableAspectJAutoProxy annotation enables AspectJ support for our beans. Simply put, AspectJ is a library created to make the use of Spring AOP easier through convenient annotations like @Pointcut.

After creating the configuration, we need to set the log level of the interceptor class to TRACE, as this is the level at which it logs messages.

For example, using Jog4j, we can achieve this through the log4j.properties file:

log4j.logger.org.springframework.aop.interceptor.PerformanceMonitorInterceptor=TRACE, stdout

For every execution of the getAge() method, we will see the TRACE message in the console log:

2017-01-08 19:19:25 TRACE 
  PersonService:66 - StopWatch 
  'com.baeldung.performancemonitor.PersonService.getFullName': 
  running time (millis) = 10

3. Custom Performance Monitoring Interceptor

If we want more control over the way the performance monitoring is done, we can implement our own custom interceptor.

For this, let’s extend the AbstractMonitoringInterceptor class and override the invokeUnderTrace() method to log the start, end, and duration of a method, as well as a warning if the method execution lasts more than 10 ms:

public class MyPerformanceMonitorInterceptor extends AbstractMonitoringInterceptor {
    
    public MyPerformanceMonitorInterceptor() {
    }

    public MyPerformanceMonitorInterceptor(boolean useDynamicLogger) {
            setUseDynamicLogger(useDynamicLogger);
    }

    @Override
    protected Object invokeUnderTrace(MethodInvocation invocation, Log log) 
      throws Throwable {
        String name = createInvocationTraceName(invocation);
        long start = System.currentTimeMillis();
        log.info("Method " + name + " execution started at:" + new Date());
        try {
            return invocation.proceed();
        }
        finally {
            long end = System.currentTimeMillis();
            long time = end - start;
            log.info("Method "+name+" execution lasted:"+time+" ms");
            log.info("Method "+name+" execution ended at:"+new Date());
            
            if (time > 10){
                log.warn("Method execution longer than 10 ms!");
            }            
        }
    }
}

The same steps for associating the custom interceptor to one or more methods as in the preceding section need to be followed.

Let’s define a pointcut for the getAge() method of PersonService and associate it to the interceptor we have created:

@Pointcut("execution(public int com.baeldung.performancemonitor.PersonService.getAge(..))")
public void myMonitor() { }
    
@Bean
public MyPerformanceMonitorInterceptor myPerformanceMonitorInterceptor() {
    return new MyPerformanceMonitorInterceptor(true);
}
    
@Bean
public Advisor myPerformanceMonitorAdvisor() {
    AspectJExpressionPointcut pointcut = new AspectJExpressionPointcut();
    pointcut.setExpression("com.baeldung.performancemonitor.AopConfiguration.myMonitor()");
    return new DefaultPointcutAdvisor(pointcut, myPerformanceMonitorInterceptor());
}

Let’s sets the log level to INFO for the custom interceptor:

log4j.logger.com.baeldung.performancemonitor.MyPerformanceMonitorInterceptor=INFO, stdout

The execution of the getAge() method produced the following output:

2017-01-08 19:19:25 INFO PersonService:26 - 
  Method com.baeldung.performancemonitor.PersonService.getAge 
  execution started at:Sun Jan 08 19:19:25 EET 2017
2017-01-08 19:19:25 INFO PersonService:33 - 
  Method com.baeldung.performancemonitor.PersonService.getAge execution lasted:50 ms
2017-01-08 19:19:25 INFO PersonService:34 - 
  Method com.baeldung.performancemonitor.PersonService.getAge 
  execution ended at:Sun Jan 08 19:19:25 EET 2017
2017-01-08 19:19:25 WARN PersonService:37 - 
  Method execution longer than 10 ms!

4. Conclusion

In this quick tutorial, we’ve introduced simple performance monitoring in Spring.