A Spring timing proxy

When developing a multi-tiered application it’s good to have an idea about the performance characteristics of the tiers. One way to do that is by running the application in a profiler. That requires some infrastructure that may not by easily available to every project however. Setting up the profiler may be non-trivial too.

Spring’s AOP capabilities provide a poor man’s alternative. We can write a proxy that records the time elapsed between method invocation start and end. Together with the controllable logging of log4j we can adequately pinpoint the slower parts of our application. In particular in the case of the typical Java web application with a clean separation between application flow, business logic and data access. At a certain stage in the development, it’s the database layer that is the most expensive part of processing a request. So knowing just which parts are most time consuming is valuable information.

We could hard-code the timing logic in the DAO methods itself, but that would be both tedious, error-prone and a permanent performance loss. Logging is the prototypical AOP example and Spring makes it easy to implement this. When using a design based on Spring, chances are that the DAO’s in the data access layer are bridged to the business logic through dependency injection.

Suppose all DAO’s are in a package named DAO, then the following Spring configuration fragment will advise all accesses of the DAO interfaces.

 <bean
    class="org.springframework.aop.framework.autoproxy.DefaultAdvisorAutoProxyCreator" />

  <bean id="timingAdvisor"
    class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">
    <property name="advice">
      <ref local="timingLogger" />
    </property>
    <property name="patterns">
      <list>
        <value>.*DAO.*</value>
      </list>
    </property>

  </bean>  <bean id="timingLogger"
    class="net.premereur.npps.services.oper.logging.TimingLoggingInterceptor"
    destroy-method="summary">
    <property name="logName" value="trace.SQLTimer" />
    <property name="debugThreshold" value="5" />
    <property name="infoThreshold" value="50" />
    <property name="warnThreshold" value="150" />
  </bean>

The first bean instructs the Spring AOP system (I’m not using the new AspectJ integration here) to look for beans that provide advice and potentially apply it to all Spring managed beans.

The second tag sets up an advisor that uses regular expression matching on the fully qualified name of methods. In this case anything with DAO in it will be matched. Since the DAO package is aptly named DAO in my case this will fulfill its role well. Note that there will be a double match because the DAO’s themselves have names ending in DAO as well. That doesn’t hurt of course. The advice is a reference to the third bean.

The timingLogger is an instance of TimingLoggingInterceptor that is configured with the name of the logger that is to be used. Indeed, it doesn’t make sense logging under the name of the Interceptor. Better to use a name that is a bit easier on the eyes. Also, it allows us to group other instrumentation logs (maybe in another blog) together. Even more interesting is the specification of the logging thresholds. The application will probably make a lot of short transactions that we don’t want to log as we will mostly focus on the long-running queries. In the present configuration, anything above 150 milliseconds will be logged at the warn facility. If we’re not interested in the shorter-running queries, we can configure the logging system not to display those. Just try to consistently implement that in each and every DAO method!

To conclude, the non completely trivial parts of the interceptor implementation:

public Object invoke(MethodInvocation invocation) throws Throwable {
  long start = System.currentTimeMillis();
  try {
    return invocation.proceed();
  } finally {
    long interval = System.currentTimeMillis() - start;
    if (interval > longestCall) {
      longestCall = interval;
    }
    if (interval < shortestCall) {
      shortestCall = interval;
    }
    averageCall = (averageCall * numCalls + interval) / (numCalls + 1);
    ++numCalls;
    try {
      if (interval >= warnThreshold && logger.isWarnEnabled()) {
        logger.warn(invocation.getMethod().getName() + ", " + interval);
      } else if (interval >= infoThreshold && logger.isInfoEnabled()) {
        logger.info(invocation.getMethod().getName() + ", " + interval);
      } else if (interval >= debugThreshold && logger.isDebugEnabled()) {
        logger.debug(invocation.getMethod().getName() + ", " + interval);
      }
    } catch (Exception e) {
      // Logging should never break things
    }
  }
}

As an added bonus, this implementation also records some simple statistics on all advised invocations. That’s where the destroy-method attribute in the bean specification is for. Upon shut-down of the application it will log the statistics as in:

public void summary() throws Exception {
  if (logger.isInfoEnabled()) {
    logger.info("Call statistics");
    logger.info("Number of calls : " + numCalls);
    if (numCalls > 0) {
      logger.info("Shortest call : " + shortestCall + "ms");
      logger.info("Longest call : " + longestCall + "ms");
    }
    logger.info("Average call : " + averageCall + "ms");
  }
}

This more useful for e.g. running unit tests than for running inside an application container since the only time the statistics are printed is right before the application stops. One can easily enhance this with Quartz to periodically dump the statistics or with JMX to request them at will. For the moment the need isn’t here…