Development Art

One critical feature missing in Hibernate is the ability to log how long queries are taking. This is vital when you are performance tuning your application to see which parts can be optimized and also can highlight issues with the database (missing indexes, fragmentation etc.). With the correct fetching and batch strategies you usually don’t have to do too much, but it is always good to know how long things are taking. It can help in defining the order in which queries should run and even identify that maybe you should be doing queries in parallel.

There are configuration options already which allow you to print the sql queries being run but nothing I have seen which allows me to do the above. btw. if anybody knows how to print the full sql query with the parameters I would love to know.

One can always write logging statements surrounding each method (usually DAO methods) running the queries, however this is quite pervasive. It would be nicer to do and change as little as possible and get query execution times. Aspect-oriented programming can help us here. The following piece is an example using Spring+Hibernate stack since this is what I use - and it makes it so easy!

For a full description on AOP head-over to wikipedia linked above - I will give a very short crash-course. The idea behind AOP is the separation of concerns. We have packages, classes and methods which assist us with separation and modularization. Some concerns though don’t fit into this idea - they ‘crosscut’ other concerns. An example is logging. Aspect oriented programming gives us additional tools by which we can separate these sorts of ‘concerns’.

So firstly the code -

package au.com.xyz.aop;

import org.apache.commons.lang.time.StopWatch;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.stereotype.Component;

@Component
@Aspect
public class DAOInterceptor {

            protected Log log = LogFactory.getLog(DAOInterceptor.class);

            @Around("execution(* au.com.xyz.dao..*.*(..))")
            public Object logHibernateQueryTimes(ProceedingJoinPoint pjp) throws Throwable {
                        StopWatch stopWatch = new StopWatch();
                        stopWatch.start();
                        Object retVal = pjp.proceed();
                        stopWatch.stop();

                        String str = pjp.getTarget().toString();
                        log.debug(str.substring(str.lastIndexOf(".")+1, str.lastIndexOf("@")) + " - " + pjp.getSignature().getName() + ": " + stopWatch.getTime() + "ms");
                        return retVal;
            }

}

The AOP class is a simple POJO with some annotations -

• @Component is Spring related - so Spring will create an instance of the bean when it scans.
• @Aspect declares that this class is an Aspect
• @Around is Aspect related - means that execute this method around the methods in the classes given by expression (i.e. before the actual method is called and after the method is called)

In the actual method you can see it is again very simple -

• Lines 19-20: I start a timer (commons StopWatch)
• Line 21: Invoke the DAO method which will run the query and keep the return value
• Line 22: Stop the timer
• Line 24-25: Log the time taken for the query
• Line 26: Return the value of the DAO method

The only other thing left to do is to configure Spring to enable AOP.

<beans xmlns:aop="http://www.springframework.org/schema/aop"
       xsi:schemaLocation="http://www.springframework.org/schema/aop
       					   http://www.springframework.org/schema/aop/spring-aop-2.5.xsd">

	<aop:aspectj-autoproxy />
</beans>

That’s it! Depending on how you’ve configured your logging, you should see output similar to the following in your log -