Spring AOP in practice – measure method execution time

Tomasz Głuszak

In this article we will take a closer look at Aspect Oriented Programming (AOP) with a little help from Spring Framework. AOP is powerful tool that can increase modularity, keep code clean and easier to read, maintain and develop.

If you are new to aspect terminology please refer to Spring documentation:

https://docs.spring.io/spring/docs/2.5.x/reference/aop.html#aop-introduction-defn

For the sake of clarity and better understanding, example code will be as simple as possible.

In our use case we want to measure and log method execution time. The simplest way to achieve that would be to modify every method we want to profile, but that is not very elegant way. We want to keep measuring code in single place and not to modify body of to-be-measured method. Using custom annotation for method will be far better solution.

Our example consists of:

  • applicationContext.xml – in here we define beans and enable AspectJ support
  • Timed.java – annotation class that will be used to mark methods that will be profiled
  • SomeService.java – sample service class that we want to monitor method execution time
  • MeasurementAspect.java – aspect class that will measure and log execution time
  • Main.java – contains main method to run example

If you are using maven following dependencies should be added to your pom.xml:

<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-context</artifactId>
    <version>4.0.0.RELEASE</version>
</dependency>
<dependency>
    <groupId>org.aspectj</groupId>
    <artifactId>aspectjweaver</artifactId>
    <version>1.8.5</version>
</dependency >

Note that spring-context includes spring-aop and AspectJ requires spring-aop dependency.

Aplication context

 <?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:aop="http://www.springframework.org/schema/aop"
       xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-2.5.xsd
    http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-2.5.xsd">

    <aop:aspectj-autoproxy />
    <bean id="measurementAspect" class="example.MeasurementAspect" />
    <bean id="someService" class="example.SomeService" />
</beans>

To enable the AspectJ support line <aop:aspectj-autoproxy /> is mandatory.

Custom annotation

First step is to create some custom annotation that will be used to put before method that we want to measure time execution.

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

It’s as simple as it gets. @interface with Target METHOD and Retention RUNTIME.

Annotation usage

Sample business operation that execution time need to be measured will look like this:

public class SomeService {
    @Timed
    public void doSomeJob() throws InterruptedException {
        System.out.println("Doing some job");
        Thread.sleep(3500);
    }
}

Our custom annotation @Timed is simply put before method. We sleep thread for some time to make method execute longer and ensure measurement is correct.

Aspect class – measurement logic

MeasurementAspect.java is core of our example. In this class goes all measurement and logging logic (itself very simple).

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

@Aspect
public class MeasurementAspect {
    @Around("@annotation(Timed)")
    public Object measureExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
        long start = System.currentTimeMillis();
        Object proceed = joinPoint.proceed();
        long executionTime = System.currentTimeMillis() - start;
        System.out.println(joinPoint.getSignature() + " executed in " + executionTime + "ms");
        return proceed;
    }
}

What this code does:

  • Using @Aspect annotation we have declared that this class is an aspect
  • Using @Around  annotation we have defined advice that will be run before and after target method
  • @annotation(Timed) is a pointcut, which means that all methods annotated with @Timed will be associated with this advice
  • Inside advice we simply measure time before and after target method execution (joinPoint.proceed()) and log difference to output

Of course logic code in here can be more complex, proper logger can by used, logical conditions can be applied, execution time can be stored for statistics etc. but we wanted to keep example as simple as possible.

Running example

Finally we can run our example

public class Main {
    public static void main(String [] args) throws InterruptedException {
        ApplicationContext context = new ClassPathXmlApplicationContext(
                "applicationContext.xml");
        SomeService someService = (SomeService) context.getBean("someService");
        someService.doSomeJob();
    }
}

Program will produce following outpout, just as expected:

Doing some job
void example.SomeService.doSomeJob() executed in 3512ms

As you can see from the example using AspectJ and Spring AOP in very few lines of code we are able to come with working solution for simple task such as monitoring method execution time.

Poznaj mageek of j‑labs i daj się zadziwić, jak może wyglądać praca z j‑People!

Skontaktuj się z nami