How to log Hibernate Cache Hits

October 01, 2009

Hibernate enables you to improve the performance of your application by using second-level caching. What does this mean? The second-level cache is capable of caching hibernate entities even when the hibernate session closes. Before loading an entity from the database the session first checks if the entity has already been cached. This can greatly reduce the number of database accesses and thus improve the performance on each cache hit.

As a consequence of using the Hibernate second-level cache, you - as a developer - have to be aware of the fact that each call of a data access method can either result in a cache hit or miss. I’m no fan of gambling so I prefer to see some log messages on accessing the cache. One possible solution is to use Hibernates built-in cache logging. You have to alter the log level, e.g. in your log4.xml:

<logger name="org.hibernate.cache">
   <level value="DEBUG" />
</logger>

My advice on this is: don’t use it! It results in horrible big numbers of log messages and thus slows the execution time.

So, let’s utilize Spring AOP to log the cache access on our DAO methods. What’s the idea behind this approach? I declare an around advice to do the logging for me. The so called CacheMonitor aspect will be woven around each DAO method, so every potential cache hit or miss will be logged. There’s only one last question to be answered: How is it possible to determine if any cache hit or miss has been occured? This is easily achievable by utilising another Hibernate feature, statistics! Each hibernate session factory is capable of generating certain statistics. These statistics contain useful information, e.g. number of commited transactions, slowest database query or… different caching data like number of cache hits or misses. Let’s take a look at the source code of the CacheMonitor aspect:

@Aspect
public class CacheMonitor {
   private final static Logger LOG = LoggerFactory.getLogger(CacheMonitor.class);
   private final static NumberFormat NF = new DecimalFormat("0.0###");

   @Autowired
   private SessionFactory sessionFactory;

   @Around("execution(* com.mycompany.myproject.dao..*.*(..))")
   public Object log(ProceedingJoinPoint pjp) throws Throwable {
      if (!LOG.isDebugEnabled()) {
         return pjp.proceed();
      }

      Statistics statistics = sessionFactory.getStatistics();
      statistics.setStatisticsEnabled(true);

      long hit0 = statistics.getQueryCacheHitCount();
      long miss0 = statistics.getSecondLevelCacheMissCount();

      Object result = pjp.proceed();

      long hit1 = statistics.getQueryCacheHitCount();
      long miss1 = statistics.getQueryCacheMissCount();

      double ratio = (double) hit1 / (hit1 + miss1);

      if (hit1 > hit0) {
         LOG.debug(String.format("CACHE HIT; Ratio=%s; Signature=%s#%s()", NF.format(ratio), pjp.getTarget().getClass().getName(), pjp.getSignature().toShortString()));
      }
      else if (miss1 > miss0){
         LOG.debug(String.format("CACHE MISS; Ratio=%s; Signature=%s#%s()", NF.format(ratio), pjp.getTarget().getClass().getName(), pjp.getSignature().toShortString()));
      }
      else {
         LOG.debug("query cache not used");
      }

      return result;
   }
}

As you can see the pointcut as defined in the @Around annotation has to be modified to point at the projects dao package. To get things working you have to add two lines of code to the Spring configuration:

<aop:aspectj-autoproxy />
<bean class="com.mycompany.myproject.aspect.CacheMonitor" />

If you got any compiler or runtime errors, ensure both spring-aop.jar and aspectj.jar has been added to the classpath of your project correctly.

Executing dao methods with the woven aspects results in log messages like this:

CACHE HIT; Ratio=0,7818; Signature=com.mycompany.myproject.dao.MyDaoImpl#find()

Read More