Performance Monitoring of Java Classes with Spring AOP

Method performance monitoring is a trivial task and with Spring AOP it doesn't require any code change, just some simple configurations. But unfortunately is not very useful on its own as it provide response time only and doesn't provide any other stats.

One easy way to have some useful stats is to write a simple interceptor class instead of using Spring default one (PerformanceMonitorInterceptor). Below is an example of this that provides periodic stats (last, average and greatest response time) as well as warning whenever a method response time exceeds a configured threshold.

package com.myapp.web.interceptor;

import java.util.concurrent.ConcurrentHashMap;

import org.aopalliance.intercept.MethodInterceptor;

import org.aopalliance.intercept.MethodInvocation;

import org.slf4j.Logger;

import org.slf4j.LoggerFactory;

public class CustomPerformanceInterceptor implements MethodInterceptor {

    Logger logger = LoggerFactory.getLogger(

        CustomPerformanceInterceptor.class.getName());   

    private static ConcurrentHashMap<String, MethodStats> methodStats = 

        new ConcurrentHashMap<String, MethodStats>();

    private static long statLogFrequency = 5;

    private static long methodWarningThreshold = 1000;  

    

    public Object invoke(MethodInvocation method) throws Throwable {

        long start = System.currentTimeMillis();

        try {

            return method.proceed();

        }

        finally {

            updateStats(method.getMethod().getName(), (System.currentTimeMillis() - start));

        }

    }

    private void updateStats(String methodName, long elapsedTime) {

        MethodStats stats = methodStats.get(methodName);

        if(stats == null) {

            stats = new MethodStats(methodName);

            methodStats.put(methodName,stats);

        }

        stats.count++;

        stats.totalTime += elapsedTime;

        if(elapsedTime > stats.maxTime) {

            stats.maxTime = elapsedTime;

        }

        if(elapsedTime > methodWarningThreshold) {

            logger.warn("method = " + methodName + "(), count = " + stats.count + ", lastTime = " + elapsedTime + ", maxTime = " + stats.maxTime);

        }

      

        if(stats.count % statLogFrequency == 0) {

            long avgTime = stats.totalTime / stats.count;

            long runningAvg = (stats.totalTime - stats.lastTotalTime) / statLogFrequency;

            logger.info("method = " + methodName + "(), count = " + stats.count + ", lastTime = " + elapsedTime + ", avgTime = " + avgTime + ", runningAvg = " + runningAvg + ", maxTime = " + stats.maxTime);

            stats.lastTotalTime = stats.totalTime;  

        }

    }

    class MethodStats {

        public String methodName;

        public long count;

        public long totalTime;

        public long lastTotalTime;

        public long maxTime;

        public MethodStats(String methodName) {

            this.methodName = methodName;

        }

    }

}

By default, it will log stats every 5 method calls and log a warning message anytime a method response time exceeds 1000ms.

You can configure this interceptor by adding the following pointcut/advisor configuration.
It will add performance logging to all methods in "com.myapp.services" package:

<bean id="customPerformanceMonitor" class="com.myapp.web.interceptor.CustomPerformanceInterceptor" />
<aop:config>
        <aop:pointcut id="allMethods" expression="execution(* com.myapp.services.*.*(..))" />
        <aop:advisor pointcut-ref="allMethods" advice-ref="customPerformanceMonitor" order="2" />
</aop:config>

Note: these classes must be instantiated with Spring. Otherwise, the AOP hooks will not be executed.
Next, setup logging to enable TRACE on the interceptor class.

<logger name="com.myapp.web.interceptor.CustomPerformanceInterceptor" additivity="false">

        <level value="TRACE" />
        <appender-ref ref="STDOUT" />
</logger>

When you run your app, you will see stat logs like this...

WARN CustomPerformanceInterceptor – method = processRequest(), count = 10, lastTime = 1072, maxTime = 1937
INFO    CustomPerformanceInterceptor – method = processRequest(), count = 10, lastTime = 1072, avgTime = 1243, runningAvg = 1243, maxTime = 1937
INFO    CustomPerformanceInterceptor – method = processRequest(), count = 20, lastTime = 1466, avgTime = 1067, runningAvg = 892, maxTime = 1937

Do not forget to include the spring-aop, and aspectj libraries.

<dependency>

        <groupId>org.aspectj</groupId>

        <artifactId>aspectjweaver</artifactId>

</dependency>

<dependency>

        <groupId>org.springframework</groupId>

        <artifactId>spring-aop</artifactId>

</dependency>

Please let me know your thoughts and suggestions. Happy coding.