Friday, August 19, 2011

Performance Monitoring With Spring AOP

If you are using Spring to access/configure resources (DAOs/services), then you might as well add some basic performance monitoring while you are at it.  This is a trivial task with Spring AOP and doesn't require any changes to existing code, just some simple configuration. 

First, you need to include the spring-aop, aspectj and cglib libraries.  If you are using Maven, simply include the following dependencies...

        <dependency>
            <groupId>org.aspectj</groupId>
            <artifactId>aspectjweaver</artifactId>
            <version>1.5.4</version>
        </dependency>
        <dependency>
            <groupId>cglib</groupId>
            <artifactId>cglib-nodep</artifactId>
            <version>2.2</version>
        </dependency>
        <dependency>
          <groupId>org.springframework</groupId>
          <artifactId>spring-aop</artifactId>
          <version>2.5.6</version>
        </dependency>


Next, identify what needs monitoring and put the AOP hooks in place.  Generally, this just requires adding a pointcut and advisor configuration in your existing Spring XML configuration file.  This configuration will add method response time logging to all methods in the "com.mycompany.services" package.  Note: these classes must be instantiated with the Spring context...otherwise, the AOP hooks will not be executed.

    <bean id="performanceMonitor"
              class="org.springframework.aop.interceptor.PerformanceMonitorInterceptor" />

    <aop:config>
        <aop:pointcut id="allServiceMethods" expression="execution(* com.mycompany.services.*.*(..))"/>
        <aop:advisor pointcut-ref="allServiceMethods" advice-ref="performanceMonitor" order="2"/>
    </aop:config>

Next, you need to setup your logging (log4j, etc) to enable TRACE on the interceptor class.

    <logger name="org.springframework.aop.interceptor.PerformanceMonitorInterceptor" additivity="false">
        <level value="TRACE"/>
        <appender-ref ref="STDOUT"/>
    </logger>

That's it, now when you run your application, you will see the following logging...

TRACE PerformanceMonitorInterceptor  - StopWatch 'PerfTestService.processRequest': running time (millis) = 1322
TRACE PerformanceMonitorInterceptor  - StopWatch 'PerfTestService.processRequest': running time (millis) = 98
TRACE PerformanceMonitorInterceptor  - StopWatch 'PerfTestService.processRequest': running time (millis) = 1764


This is a some great raw data, but unfortunately is not very useful on its own.  Its for every method call and doesn't provide any other stats.  This quickly clutters up the log and without some way to process/aggregate the log entries, its hard to make sense out of it.  So, unless you plan of writing some log parsing or using 3rd party software (like Splunk or Cati), then you really should do some processing of the data before writing it to the log file.


One easy way to do this is to just write a simple interceptor class to use instead of the 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.

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

public class PerfInterceptor implements MethodInterceptor {

     Logger logger = LoggerFactory.getLogger(PerfInterceptor.class.getName());
    private static ConcurrentHashMap<String, MethodStats> methodStats = new ConcurrentHashMap<String, MethodStats>();
    private static long statLogFrequency = 10;
    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 warning: " + methodName + "(), cnt = " + 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.debug("method: " + methodName + "(), cnt = " + stats.count + ", lastTime = " + elapsedTime + ", avgTime = " + avgTime + ", runningAvg = " + runningAvg + ", maxTime = " + stats.maxTime);
           
            //reset the last total time
            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;
        }
    } 
}


Now, you just need to wire this into your app by referencing this class in your Spring xml and logging config.  When you run your app, you will see stats like this...

WARN  PerfInterceptor - method warning: processRequest(), cnt = 10, lastTime = 1072, maxTime = 1937
TRACE PerfInterceptor - method: processRequest(), cnt = 10, lastTime = 1072, avgTime = 1243, runningAvg = 1243, maxTime = 1937
WARN  PerfInterceptor - method warning: processRequest(), cnt = 20, lastTime = 1466, maxTime = 1937
TRACE PerfInterceptor - method: processRequest(), cnt = 20, lastTime = 1466, avgTime = 1067, runningAvg = 892, maxTime = 1937

As you can see, these stats can provide valuable feedback about class/method performance with very little effort and without modifying any existing Java code.  This information can easily be used to find bottlenecks in your application (generally database or threading related, etc)...good luck

This page has been translated into Spanish language by Maria Ramos from Webhostinghub.com

4 comments:

  1. Did you take a look at org.springframework.aop.interceptor.JamonPerformanceMonitorInterceptor ?

    this one also collects bucket of response tim
    e and also information about concurrent access.

    Often max, min, avg aren't enough, depending on arguments the distribution can be quite different. see http://mestachs.wordpress.com/2012/03/31/performance-when-average-is-not-enough/

    ReplyDelete
  2. Great article, I am considering adding this kind of efficient reporting to my application. Do you know how this will itself impact performance?

    ReplyDelete
  3. I have a minimal set always running (+/- url)
    and 'red button' to enable more details (spring aop methods)
    another 'ultra red button' to enable sql.

    From the minimal set I'm injecting some statistics in nagios and splunk.

    For our end-users it's nearly invisible a few ms for a complete transaction.
    I enable it for a complete day often after a release just to take the temperature or in case we missed a required index or see if something looks "slower" than it used to.

    The main drawback in my production environment is the memory consumption because some sql are not reused (create table temp001,create table temp002,...)
    so they "stack" into memory. I've a cron job in jenkins that reset periodically through the jamon jsp. The same kind of issue is observable if you enable the jamon servlet filter and you have rest url (/user/123.json,...)

    ReplyDelete
  4. Hi,
    Can you share the spring config and log4j config for "PerfInterceptor".
    I am trying ti replicate it and somehow the "PerfInterceptor" is not picked up for logging

    ReplyDelete