iBatis "Cache Miss", Part 1 - Validating the problem

There is a lot of information to cover on this topic, so this will be a series of three blogs. First a little background. The project I am on, noticed some performance issues as we had more and more users. As a result, we decided to cache the heavily used, infrequently modified iBatis selects. At the time a lot of investigation was done to verify that the cache models were set up correctly and working.

Unfortunately, all the testing was done manually. So as fate would have it, subsequent changes ended up breaking the caching. However, due to upgrades and other optimizations in the hardware and software it was not immediately obvious that this had occurred. As a result, the project progressed for nearly a year with caching broken.

In this first blog I want to discuss how we were able to verify that caching was broken through JBoss logging. The second blog will discuss how to write an integration test that can be automated using maven, to prevent the caching from being broken in the future. The final blog, will cover a discussion of the iBatis cacheModel and how to configure it.

First, you will need to modify the jboss-log4j.xml file in the $JBOSS_HOME/server/default/conf directory. You will need to add a new appender definition as well as set up the categories you want to be output to that file. This information was found in this post. Here are the exerts from that file.

   <appender name="SQL_FILE" 
      class="org.jboss.logging.appender.DailyRollingFileAppender">
      <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
      <param name="File" value="${jboss.server.log.dir}/sql.log"/>
      <param name="Append" value="false"/>
      <param name="DatePattern" value="'.'yyyy-MM-dd"/>
      <layout class="org.apache.log4j.PatternLayout">
         <param name="ConversionPattern" value="%d %-5p [%c] %m%n"/>
      </layout>
   </appender>

   <category name="java.sql" additivity="false">
     <priority value="DEBUG" />
     <appender-ref ref="SQL_FILE"/>
   </category>

   <category name="com.ibatis" additivity="false">
     <priority value="DEBUG" />
     <appender-ref ref="SQL_FILE"/>
   </category>

When verifying this we started with our simplest example. A single table that did not join to other tables. From the client we brought up our admin interface for that table. This performed the initial select of everything which set up the cache. Refreshing, without having performed an insert, update, or delete should have returned the same results from the cacheModel. Much to our surprise, what we saw was "Cache Miss".

2010-03-01 13:43:56,515 DEBUG [com.ibatis.sqlmap.engine.cache.CacheModel] Cache
                   'LocationType.locationType_cache': cache miss
2010-03-01 13:59:41,921 DEBUG [java.sql.Connection] {conn-102346} 
                   Preparing Statement:          SELECT ...
2010-03-01 13:59:41,921 DEBUG [java.sql.PreparedStatement] {pstm-102347} 
                   Executing Statement:          SELECT ...
2010-03-01 13:59:41,921 DEBUG [java.sql.PreparedStatement] {pstm-102347} 
                   Parameters: []

Now that we have been able to manually verify that the cacheModel is broken, we need to write some automated tests so this doesn't happen again. That is the subject of of the next blog, iBatis "Cache Miss", Part 2.

After fixing the cacheModel the result was quite different.

2010-03-01 14:01:28,109 DEBUG [java.sql.Connection] {conn-102351} Connection
2010-03-01 14:01:28,109 DEBUG [com.ibatis.sqlmap.engine.cache.CacheModel] Cache 
    'LocationType.locationType_cache': retrieved object 'LocationType name: ...'

As you can see from the above log entries, it retrieved the results from the cache. Now when you do an insert, this is the output you will see:

2010-03-01 14:06:20,421 DEBUG [java.sql.Connection] {conn-102352} Connection
2010-03-01 14:06:20,421 DEBUG [java.sql.Connection] {conn-102352} 
       Preparing Statement:          INSERT ...
2010-03-01 14:06:20,421 DEBUG [java.sql.PreparedStatement] {pstm-102353} 
       Executing Statement:          INSERT ...
2010-03-01 14:06:20,421 DEBUG [java.sql.PreparedStatement] {pstm-102353} 
       Parameters: [Weather, null, location.type.weather, 1, jp1@test.com]
2010-03-01 14:06:20,421 DEBUG [java.sql.PreparedStatement] {pstm-102353} 
       Types: [java.lang.String, null, java.lang.String, java.lang.Integer, java.lang.String]
2010-03-01 14:06:20,703 DEBUG [com.ibatis.sqlmap.engine.cache.CacheModel] 
       Cache 'Location.new_locations_cache': flushed
2010-03-01 14:06:20,703 DEBUG [com.ibatis.sqlmap.engine.cache.CacheModel] 
       Cache 'LocationType.locationType_cache': flushed

Reviewing these log statements you can see that both the Location and LocationType cache was flushed, when the insert was performed. The next select that is done will hit the database again and cache the values returned.