Measuring Method Execution Times With Spring AOP and AspectJ in Spring Boot

Hey, all! Today, I will be talking about how to measure average method execution times using AspectJ with a Spring Boot application. We will declare a quartz job and log the average method executions.

First, we will define our pom.xml, like the following:

<?xml version="1.0" encoding="UTF-8"?>
<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>AspectProgramming</groupId>
    <artifactId>com.sample</artifactId>
    <version>1.0-SNAPSHOT</version>

    <packaging>war</packaging>

    <properties>
        <java.version>1.8</java.version>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
    </properties>

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

    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-context-support</artifactId>
        </dependency>


        <dependency>
            <groupId>org.quartz-scheduler</groupId>
            <artifactId>quartz</artifactId>
            <version>2.2.1</version>
        </dependency>

        <dependency>
            <groupId>log4j</groupId>
            <artifactId>log4j</artifactId>
            <version>1.2.17</version>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-log4j12</artifactId>
            <version>1.7.13</version>
        </dependency>
        <dependency>
            <groupId>org.apache.commons</groupId>
            <artifactId>commons-lang3</artifactId>
            <version>3.4</version>
        </dependency>
        <dependency>
            <groupId>commons-logging</groupId>
            <artifactId>commons-logging</artifactId>
            <version>1.2</version>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-tomcat</artifactId>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>
    </dependencies>


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


</project>

Next, we need to create a Spring Boot application configuration:

@SpringBootApplication
public class MyApplication {
    public static void main(String[] args) throws InterruptedException {
            SpringApplication.run(MyApplication.class, args);
        }
}

In order to activate our aspect logging in Spring beans, we declare a new annotation named as  “Loggable."

@Target({ElementType.METHOD, ElementType.TYPE})
@Retention(RetentionPolicy.RUNTIME)
public @interface  Loggable {
}

We use Target with the attribute ElementType.Method, which is used for method definitions, and we use ElementType.Type for class definitions.

In order to make annotations available at runtime in the JVM, we use the RetiontionPolicy.Runtime  configuration.

Next, we create a class named LoggingAspect, which contains an empty method named “loggable." We use@Pointcut advice using the within designator in order to determine when advice annotations will be executed.

public class LoggingAspect {
@Pointcut("within(@com.aspect.logging.Loggable *)")
public void loggable() 
}
}

We create two methods named beforeMethodStatistics and afterMethodStatistics.

We use "Before" advice in the method beforeMethodStatistics in order to get time in milliseconds just before the method execution occurs. It calls JointPoint as a parameter to capture the parameters passed in the method execution.

@Before("loggable()")
public void beforeMethodStatistics(JoinPoint jp) throws Throwable {
    Object[] args = jp.getArgs();
    if (null != args && args.length > 0) {
        for (Object arg : args) {
            if (arg instanceof BaseRequest) {
                ((BaseRequest) arg).setStartTimeInMillis(Calendar.getInstance().getTimeInMillis());
                break;
            }
        }
    }
}

Inside the afterMethodStatistics method, we use "After"  advice to calculate the total time after the method execution.

@After("loggable()")
public void afterMethodStatistics(JoinPoint jp) {
    Object[] args = jp.getArgs();
    if (null != args && args.length > 0) {
        for (Object arg : args) {
            if (arg instanceof BaseRequest) {
                StatisticsUtils.calculateStatistics(jp, arg, StatisticsMapEnum.ASPECT_LOGGER_STATISTICS_MAP);
                break;
            }
        }
    }
}

We create the calculateStatistics method to set up the method execution count and total execution time. The LogMethodStatistics method is used to log the average time.

public class StatisticUtils {

    private static AppLogger logger = AppLoggerFactory.getLogger(StatisticUtils.class);

    public static void calculateStatistics(JoinPoint jp, Object arg, StatisticsMapEnum  statisticsMapEnum) {

        try {
            long resultTimemMillis = Calendar.getInstance().getTimeInMillis() - ((BaseRequest) arg).getStartTimeInMillis();


            StatisticsDto statisticsDto;
            Map<String, StatisticsDto> statisticsMap = CacheUtils.statisticsMap.get(statisticsMapEnum);
            if (GeneralUtils.isNullOrEmptyMap(statisticsMap))
                statisticsMap = new HashMap<>();
            if (GeneralUtils.isNullObject(statisticsMap.get(jp.getSignature().getName()))) {
                statisticsDto = new StatisticsDto();
                statisticsDto.setMethodName(jp.getSignature().getName());
                statisticsDto.setTotalTimeInMillis(resultTimemMillis);
 statisticsDto.setMethodCallCount(1);
            } else {
                statisticsDto = statisticsMap.get(jp.getSignature().getName());
                long totalTimeInMillis = statisticsDto.getTotalTimeMillis() + resultTimemMillis;
                statisticsDto.setTotalTimeInMillis((totalTimeInMillis));
                statisticsDto.setMethodCallCount(statisticsDto.getMethodCallCount() +1);
            }
            statisticsMap.put(jp.getSignature().getName(), statisticsDto);
            CacheUtils.statisticsMap.put(statisticsMapEnum,statisticsMap);
        } catch (Exception ex) {
            logger.error("Exception Occured while calculating statistics:" + ExceptionUtils.getStackTrace(ex));
        }
    }

    public static void logMethodStatistics(StatisticsMapEnum  statisticsMapEnum, BatchTypeEnum batchTypeEnum) {

        try {
            Map<String, StatisticsDto> statisticsDtoMap = CacheUtils.statisticsMap.get(statisticsMapEnum);
            if (!GeneralUtils.isNullOrEmptyMap(statisticsDtoMap)) {
                logger.info(batchTypeEnum.toString() + " Statistics: MethodName  -  MethodAverageTime (millis)");
                Set<Map.Entry<String, StatisticsDto>> entrySet = statisticsDtoMap.entrySet();
                Iterator<Map.Entry<String, StatisticsDto>> iterator = entrySet.iterator();
                while (iterator.hasNext()) {
                    Map.Entry<String, StatisticsDto> entry = iterator.next();
                    StatisticsDto statisticsDto = entry.getValue();
                    logger.info(statisticsDto.getMethodName() + " - " + Long.valueOf(statisticsDto.getTotalTimeMillis() / statisticsDto.getMethodCallCount()) + " ms");
                }
            }
            statisticsDtoMap = new HashMap<>();
            CacheUtils.statisticsMap.put(statisticsMapEnum,statisticsDtoMap);
        } catch (Exception ex) {
            logger.error("Exception Occured while logging statistics:" + ExceptionUtils.getStackTrace(ex));
        }
    }}

So, let's create three services as ControlService, PersistService, and  FetchDataService.

In order to intercept those services methods, we use our "Loggable" annotation and activate the method interception.

@Loggable
@Service
public class ControlServiceImpl implements ControlService {

    public void makeSomeCheck(FetchDataRequest request)
    {

        try {
            Thread.sleep(new Random().nextInt(2000)+1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }

    }

}
@Loggable
@Service
public class FetchDataServiceImpl  implements FetchDataService{
    @Override
    public void fetchSomeData(FetchDataRequest request) {

        try {
            FetchDataDto fetchDto=new FetchDataDto();
            List<FetchDataDto> fetchDataDtoList=new ArrayList<>();

            fetchDto.setId(1001L);
            fetchDto.setName("Tom");
            fetchDto.setSurName("Walker");
            fetchDto.setAddressInfo("Chicago");
            fetchDataDtoList.add(fetchDto);

            fetchDto.setId(1002L);
            fetchDto.setName("Clark");
            fetchDto.setSurName("Michigan");
            fetchDto.setAddressInfo("New York");
            fetchDataDtoList.add(fetchDto);
            fetchDto.setId(1003L);
            fetchDto.setName("Tom");
            fetchDto.setSurName("Walker");
            fetchDto.setAddressInfo("Chicago");
            fetchDataDtoList.add(fetchDto);

            fetchDto.setId(1004L);
            fetchDto.setName("Clark");
            fetchDto.setSurName("Michigan");
            fetchDto.setAddressInfo("New York");
            fetchDataDtoList.add(fetchDto);
            fetchDto.setId(1005L);
            fetchDto.setName("Tom");
            fetchDto.setSurName("Walker");
            fetchDto.setAddressInfo("Chicago");
            fetchDataDtoList.add(fetchDto);

            fetchDto.setId(1006L);
            fetchDto.setName("Clark");
            fetchDto.setSurName("Michigan");
            fetchDto.setAddressInfo("New York");
            fetchDataDtoList.add(fetchDto);

            request.setFetchDataDtoList(fetchDataDtoList);

            Thread.sleep(new Random().nextInt(2000)+1000);

        } catch (InterruptedException e) {
            e.printStackTrace();
        }


    }
}

@Loggable
@Service
public class PersistDataServiceImpl implements PersistDataService {

    @Override
    public void persist(FetchDataRequest request) {

        try {
            Thread.sleep(new Random().nextInt(2000)+1000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

So, we generate a job called SomeJob to execute our services. The job will fetch data, perform a check, and persist to DB.

After that, it will log the average execution time on every job that execution occurs.

@Component
public class SomeJob implements Job {

    @Override
    public void execute(JobExecutionContext context) throws JobExecutionException {


        FetchDataService fetchDataService = (FetchDataService) ApplicationContextProvider.getApplicationContext().getBean("fetchDataServiceImpl");
        ThreadPoolService threadPoolService = (ThreadPoolService) ApplicationContextProvider.getApplicationContext().getBean("threadPoolServiceImpl");
        PersistDataService persistDataService =(PersistDataService) ApplicationContextProvider.getApplicationContext().getBean("persistDataServiceImpl");
        ControlService controlService =(ControlService) ApplicationContextProvider.getApplicationContext().getBean("controlServiceImpl");
        FetchDataRequest request=new FetchDataRequest() ;
        fetchDataService.fetchSomeData(request);
        controlService.makeSomeCheck(request);
        persistDataService.persist(request);

        StatisticsUtils.logMethodStatistics(BatchTypeEnum.ASPECT_LOGGER_JOB);

    }
}

Here are the results:

ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 2936 ms
persist - 1825 ms
fetchSomeData - 1487 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 1777 ms
persist - 2040 ms
fetchSomeData - 2790 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 1364 ms
persist - 1677 ms
fetchSomeData - 2531 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 2515 ms
persist - 1711 ms
fetchSomeData - 1470 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 2321 ms
persist - 2967 ms
fetchSomeData - 1789 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 1672 ms
persist - 1699 ms
fetchSomeData - 2559 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 1042 ms
persist - 2975 ms
fetchSomeData - 1165 ms
ASPECT_LOGGER_JOB Statistics: MethodName - MethodAverageTime (millis)
makeSomeCheck - 1004 ms
persist - 1531 ms
fetchSomeData - 1151 ms