TimeoutException ERROR messages reported indicating that write lock could not be acquired after 0ms

This is primarily due to unnecessary contention for certain nodes due to an inefficient cache structure used by Hibernate prior to 3.2.0.GA.

See http://opensource.atlassian.com/projects/hibernate/browse/HHH-1796 for details.

Explanation:

Under load, JBossCache can report an ERROR looking something like this:

org.jboss.cache.lock.TimeoutException: write lock for xxx could not be acquired after 0 ms. Locks: 
  Read lock owners: [] 
  Write lock owner: Thread[TP-ProcessorX,Y,Z](caller=Thread[TP-ProcessorX,Y,Z], lock info: write owner=Thread[TP-ProcessorX,Y,Z] (activeReaders=0, activeWriter=Thread[TP-ProcessorX,Y,Z], waitingReaders=0, waitingWriters=0, waitingUpgrader=0)) 

JBossCache has a special method to attempt to write something and wait 0ms for a lock acquisition. This method is called

putFailFast()

on

org.jboss.cache.TreeCache

. If another object has a concurrent write lock, this method will fail.

This is what Hibernate does when an object is detected not to be in second level cache:

1. cache.get("/packagename/PK");

2. if the cache.get returns null, call cache.putFailFast("/packagename/pk", "key", your POJO wrapped into Hibernate cache object)

3. If the putFailFast fails, swallow the exception and continue. Nothing has been added to cache yet so there are no worries about stale cache data.

Solution:

JBossCache 1.3.0 contains two new mechanisms to overcome this:

1. Using optimistic locking that will also allow greater concurrency.

2. Using The OPTIONS API (JBossCacheOptionsAPI) that allows Hibernate to set the failSilently option, which will suppress those noisy (and potentially alarming) ERROR messages.

To use these though, you'd need to use the new OptimisticTreeCache/OptimisticTreeCacheProvider (instead of TreeCacheProvider) which is only available in the Hibernate 3.2.x tree.

In normal circumstances, when Hibernate does an updated, it will do a 'cache.put' instead. This method will wait for whatever the LockAcquisitionTimeout is in your cache configuration XML file. An update should keep the cache up to date.

Workaround:

If upgrading to Hibernate 3.2.x and JBoss Cache 1.3.0 or later is not an option for you, a workaround is to configure your logging framework to suppress ERROR logging of the "org.jboss.cache.lock.IdentityLock" category.  In this use case, not acquiring the lock in 0 ms is a normal operation, so ERROR level logging is too high.

If other lock acquisition problems occur besides the "putFailFast" case described above, the exception will propagate and be logged by higher layers.  So, suppressing ERROR logging of the "org.jboss.cache.lock.IdentityLock" category will not result in silent failures.

Another Scenario:

If you're using AS 4.0.5.GA with EJB3 RC9 Patch1, this exception can still be reported even though AS 4.0.5.GA comes with Hibernate 3.2.0.GA and JBoss Cache 1.4.0.SP1. This is because from EJB3 RC9 Patch1 onwards (even on AS/EAP 4.2.x/4.3.x) org.jboss.ejb3.entity.JBCCache Hibernate cache provider is used that calls TreeCache.putFailFast().

The noisy error and stacktrace is not reported though in AS/EAP 4.2.x+ because the JBoss Cache version used here (1.4.1.x) is less noisier than JBoss Cache 1.4.0.SP1. Bottom line, if you're using AS 4.0.5.GA with EJB3 RC9 Patch1 and you see these exceptions, either:

a) Upgrade JBoss Cache version in AS 4.0.5.GA to 1.4.1.x.

b) Or upgrade to AS/EAP 4.2.x+.