Testing out the cache

In earlier posts we saw the settings needed for configuring Hibernate's second level cache and the various caches providers supported by Hibernate.
To test out the configurations for Eh Cache, I simply executed a main method to start and create a session factory.
The logs are as below:
The first set of logs are concerned with the Ehcache start:

...
109  [main] DEBUG net.sf.ehcache.CacheManager  - Configuring ehcache from classp
ath.
109  [main] DEBUG net.sf.ehcache.config.ConfigurationFactory  - Configuring ehca
che from ehcache.xml found in the classpath: file:/D:/work/Hibernate/Hibernate%2
0workspace/Caching/bin/ehcache.xml
109  [main] DEBUG net.sf.ehcache.config.ConfigurationFactory  - Configuring ehca
che from URL: file:/D:/work/Hibernate/Hibernate%20workspace/Caching/bin/ehcache.
xml
125  [main] DEBUG net.sf.ehcache.config.ConfigurationFactory  - Configuring ehca
che from InputStream
141  [main] DEBUG net.sf.ehcache.config.DiskStoreConfiguration  - Disk Store Pat
h: C:\DOCUME~1\ADMINI~1\LOCALS~1\Temp\
156  [main] DEBUG net.sf.ehcache.config.ConfigurationHelper  - No CacheManagerEv
entListenerFactory class specified. Skipping...
156  [main] DEBUG net.sf.ehcache.config.ConfigurationHelper  - No CachePeerProvi
derFactoryConfiguration specified. Not configuring a CacheManagerPeerProvider.
531  [main] DEBUG net.sf.ehcache.config.ConfigurationHelper  - No BootstrapCache
LoaderFactory class specified. Skipping...

The next step involved creating the different cache regions

563  [main] DEBUG net.sf.ehcache.store.MemoryStore  - Initialized net.sf.ehcache

.store.LruMemoryStore for com.object.cache.BookType 

563  [main] DEBUG net.sf.ehcache.store.LruMemoryStore  - com.object.cache.BookTy
pe Cache: Using SpoolingLinkedHashMap implementation
563  [main] DEBUG net.sf.ehcache.Cache  - Initialised cache: com.object.cache.Bo
okType
...
1109 [main] DEBUG org.hibernate.cache.CacheFactory  - instantiating cache region
: com.object.cache.BookType usage strategy: read-only
1109 [main] WARN  org.hibernate.cache.CacheFactory  - read-only cache configured
 for mutable class: com.object.cache.BookType

Hibernate has now configured all the class caches. The next step was creating the remaining cache regions:

1297 [main] INFO  org.hibernate.cache.UpdateTimestampsCache  - starting update 

timestamps cache at region: org.hibernate.cache.UpdateTimestampsCache
1297 [main] WARN  org.hibernate.cache.EhCacheProvider  - Could not find configur
ation [org.hibernate.cache.UpdateTimestampsCache]; using defaults.
1313 [main] DEBUG net.sf.ehcache.store.DiskStore  - Deleting data file org.hiber
nate.cache.UpdateTimestampsCache.data
1313 [main] DEBUG net.sf.ehcache.store.MemoryStore  - Initialized net.sf.ehcache
.store.LruMemoryStore for org.hibernate.cache.UpdateTimestampsCache
1313 [main] DEBUG net.sf.ehcache.store.LruMemoryStore  - org.hibernate.cache.Upd
ateTimestampsCache Cache: Using SpoolingLinkedHashMap implementation
... 
1313 [main] DEBUG net.sf.ehcache.Cache  - Initialised cache: org.hibernate.cache
.UpdateTimestampsCache
1313 [main] DEBUG org.hibernate.cache.EhCacheProvider  - started EHCache region:
 org.hibernate.cache.UpdateTimestampsCache
1328 [main] INFO  org.hibernate.cache.StandardQueryCache  - starting query cache
 at region: org.hibernate.cache.StandardQueryCache
1328 [main] WARN  org.hibernate.cache.EhCacheProvider  - Could not find configur
ation [org.hibernate.cache.StandardQueryCache]; using defaults.
1328 [main] DEBUG net.sf.ehcache.store.DiskStore  - Deleting data file org.hiber
nate.cache.StandardQueryCache.data
1344 [main] DEBUG net.sf.ehcache.store.MemoryStore  - Initialized net.sf.ehcache
.store.LruMemoryStore for org.hibernate.cache.StandardQueryCache
1344 [main] DEBUG net.sf.ehcache.store.LruMemoryStore  - org.hibernate.cache.Sta
ndardQueryCache Cache: Using SpoolingLinkedHashMap implementation
1344 [main] DEBUG net.sf.ehcache.Cache  - Initialised cache: org.hibernate.cache
.StandardQueryCache
1344 [main] DEBUG org.hibernate.cache.EhCacheProvider  - started EHCache region:
 org.hibernate.cache.StandardQueryCache

Now that all the setup is done, the cache system is ready for use.Consider the below test method:

public static void testObjects() {
    Session session1 = sessionFactory.openSession();
    BookType bookType1 = (BookType) session1.get(BookType.class, 1);
    // Loading the same record in the session
    BookType bookType1Again = (BookType) session1.get(BookType.class, 1);
    System.out.println("Are records identical in memory ? : "
        + (bookType1Again==bookType1));
    session1.close();

    Session session2 = sessionFactory.openSession();
    BookType bookTypeFromSession2 = (BookType) session2.get(
        BookType.class, 1);
    // Loading the same record in the session
    System.out.println(
        "Are records From Different sessions identical in memory ? : "
        + (bookType1Again==bookTypeFromSession2));
    System.out.println(
        "Are records From Different sessions identical in database ? : "
        + bookType1Again.getId().equals(bookTypeFromSession2.getId()));
    Statistics statistics = sessionFactory.getStatistics();
    statistics.logSummary();
    session2.close();
}

The output is as below:

1343 [main] DEBUG org.hibernate.cache.EhCache  - key: com.object.cache.BookType#1
1343 [main] DEBUG net.sf.ehcache.store.MemoryStore  - com.object.cache.BookTypeC
ache: com.object.cache.BookTypeMemoryStore miss for com.object.cache.BookType#1
1343 [main] DEBUG net.sf.ehcache.Cache  - com.object.cache.BookType cache - Miss
1343 [main] DEBUG org.hibernate.cache.EhCache  - Element for com.object.cache.Bo
okType#1 is null
1343 [main] DEBUG org.hibernate.SQL  - 
    /* load com.object.cache.BookType */ 

    select
        booktype0_.ID as ID0_0_,
        booktype0_.NAME as NAME0_0_ 
    from
        BOOK_TYPE_MASTER booktype0_ 
    where
        booktype0_.ID=?
...
1421 [main] DEBUG org.hibernate.cache.ReadOnlyCache  - Caching: com.object.cache
.BookType#1

The logs indicate that Hibernate first looked in the second level cache. (The key format is the fully qualified class name followed by the id). On not finding the record it loaded the record from the database and also added it to the cache. After this we tried to load the record from the session again.

Are records identical in memory ? : true

As can be seen no query was executed, no call to the second level cache. The record was found in the session level cache and loaded from there itself. I next created a separate session and attempted o load the record from there:

1437 [main] DEBUG org.hibernate.cache.EhCache  - key: com.object.cache.BookType#1
1437 [main] DEBUG net.sf.ehcache.store.MemoryStore  - com.object.cache.BookTypeC
ache: com.object.cache.BookTypeMemoryStore hit for com.object.cache.BookType#1
1437 [main] DEBUG org.hibernate.cache.ReadOnlyCache  - Cache hit: com.object.cac
he.BookType#1
Are records From Different sessions identical in memory ? : false
Are records From Different sessions identical in database ? : true

As can be seen above,

1. The call from the next session resulted in a Cache hit. 
2. The data for BookType with id 1 was found in the cache and was used to create the object thus avoiding a database query. 
3. As can be seen this object is in a different location in memory - this means that sessionFactory does not cache Java objects in the second level cache. It actually holds the data in a dis-assembled state and uses it to create and return the requested object.  

 From the Statistics I found the following details:

1468 [main] INFO  org.hibernate.stat.StatisticsImpl  - second level cache hits: 1
1468 [main] INFO  org.hibernate.stat.StatisticsImpl  - second level cache misses: 1
1468 [main] INFO  org.hibernate.stat.StatisticsImpl  - entities loaded: 1

On code completion:

1468 [main] DEBUG net.sf.ehcache.store.MemoryStore  - org.hibernate.cache.Standa
rdQueryCache is persistent. Spooling 0 elements to the disk store.
1468 [main] DEBUG net.sf.ehcache.store.DiskStore  - Deleting file org.hibernate.
cache.StandardQueryCache.data
1484 [main] DEBUG net.sf.ehcache.store.MemoryStore  - org.hibernate.cache.Update
TimestampsCache is persistent. Spooling 0 elements to the disk store.
1484 [main] DEBUG net.sf.ehcache.store.DiskStore  - Deleting file org.hibernate.
cache.UpdateTimestampsCache.data

Consider the below code :

public static void testObjectEviction() {
    Session session1 = sessionFactory.openSession();
    session1.get(BookType.class, 1);

    Session session2 = sessionFactory.openSession();
    sessionFactory.evict(BookType.class);
    // Loading the same record in the session
    session2.get(BookType.class, 1);
    session2.close();

    sessionFactory.evict(BookType.class, 1);
    Session session3 = sessionFactory.openSession();
    session3.get(BookType.class, 1);
    session3.close();
}

As we have the second level cache active, we would have expected the query to be fired only once - the first time. Instead the result indicates the same query was fired thrice :

Hibernate: 
    /* load com.object.cache.BookType */ 
    select
        booktype0_.ID as ID0_0_,
        booktype0_.NAME as NAME0_0_ 
    from
        BOOK_TYPE_MASTER booktype0_ 
    where
        booktype0_.ID=?
Hibernate: 
    /* load com.object.cache.BookType */ 
    select
        booktype0_.ID as ID0_0_,
        booktype0_.NAME as NAME0_0_ 
    from
        BOOK_TYPE_MASTER booktype0_ 
    where
        booktype0_.ID=?
Hibernate: 
    /* load com.object.cache.BookType */ 
    select
        booktype0_.ID as ID0_0_,
        booktype0_.NAME as NAME0_0_ 
    from
        BOOK_TYPE_MASTER booktype0_ 
    where
        booktype0_.ID=?

The reason for this was sessionFactory.evict(). SessionFactory's Evict method causes an element to be removed from the second level cache. In the first call we removed all entries for BookType class, whereas in the second call we chose to remove a specific BookType record.  
The call can be made anywhere - before or after opening a session. The important thing is it only affects the second level cache. Any record loaded in the session will not be loaded again.