Monitoring the performance of Spring method execution

This tutorial discusses how to monitor the performance of Spring applications with regards to method execution, using AspectJ open source framework.

Traditionally, the simplest way to monitor the time spent on each Java method is to include some lines of traces at the beginning and at the end of a method:

public void slowMethod() {
  long start = System.currentTimeMillis();
  class.method();
  long time = System.currentTimeMillis() - start;
  logger.trace("Time spent " + time);
}

That would easily turn into a nightmare if you have lots of methods to check to find which one is impacting your performance.

AspectJ to rescue

AspectJ is a complete implementation of the AOP technology in Java so it can virtually be applied in any java class. The peculiarity of this framework is that weaving of aspect can perform with a post compilation of your code through bytecode modification. This is different from Spring AOP where the weaving of Aspects will be performed by the container at container start-up.

Let’s see a practical example of it. The @AspectJ support is enabled by including the following element inside your spring configuration:

<aop:aspectj-autoproxy />

With the @AspectJ support enabled, any bean defined in your application context with a class that is an @AspectJ aspect (has the @Aspect annotation) will be automatically detected by Spring and used to configure Spring AOP:

package com.sample;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;

@Aspect
public class MyProfiler {
  @Pointcut("execution(* com.sample.*.*(..))")
  public void businessMethods() {}

  @Around("businessMethods()")
  public Object profile(ProceedingJoinPoint pjp) throws Throwable {
    long start = System.currentTimeMillis();
    System.out.println("Going to call the method." + pjp.getTarget());
    Object output = pjp.proceed();
    System.out.println("Method execution completed." + pjp.getTarget());
    long elapsedTime = System.currentTimeMillis() - start;
    System.out.println("Method execution time: " + elapsedTime + " milliseconds.");
    return output;
  }
}

The @Pointcut declaration has two parts: a signature including a name and any parameters, and a pointcut expression that determines which method executions we are dealing with. In our case, we are intereted to capture the execution of all Classes belonging to the com.sample.* namespace.

The last annotation included is @Around. The @Around advice runs “around” a matched method execution. It has the opportunity to do work both before and after the method executes, and to determine when, how, and even if, the method actually gets to execute at all.

That’s all we need to monitor the timing of our Classes in the com.sample namespace. Include the definition of the above Bean in your configuration:

<bean id="myProfiler" class="com.sample.MyProfiler" />

Finally, add the following dependencies to build your application:

<?xml version="1.0" encoding="UTF-8"?><project>
   <dependency>
           
      <groupId>org.springframework</groupId>
           
      <artifactId>spring-core</artifactId>
           
      <version>${spring.version}</version>
       
   </dependency>
    
   <dependency>
           
      <groupId>org.springframework</groupId>
           
      <artifactId>spring-context</artifactId>
           
      <version>${spring.version}</version>
       
   </dependency>
     
   <!-- AOP -->
    
   <dependency>
           
      <groupId>org.springframework</groupId>
           
      <artifactId>spring-aop</artifactId>
           
      <version>${spring.version}</version>
       
   </dependency>
    
   <dependency>
           
      <groupId>org.aspectj</groupId>
           
      <artifactId>aspectjweaver</artifactId>
           
      <version>${aspectj.version}</version>
       
   </dependency>
</project>