Debugging Hibernate/Ehcache deadlock

Question

We are using Ehcache version 2.4.4 with Hibernate 3.5.5-FINAL. I've got a strange case happening on my debug environment - it looks like Ehcache is getting into a deadlock. Here's the relevant bit of the stack trace:

http-8080-2@7345 daemon, prio=5, in group 'main', status: 'WAIT'
      at sun.misc.Unsafe.park(Unsafe.java:-1)
      at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:842)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1178)
      at java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:807)
      at net.sf.ehcache.store.compound.Segment.put(Segment.java:427)
      at net.sf.ehcache.store.compound.CompoundStore.put(CompoundStore.java:141)
      at net.sf.ehcache.Cache.putInternal(Cache.java:1434)
      at net.sf.ehcache.Cache.put(Cache.java:1367)
      at net.sf.ehcache.Cache.put(Cache.java:1339)
      at net.sf.ehcache.constructs.EhcacheDecoratorAdapter.put(EhcacheDecoratorAdapter.java:111)
      at net.sf.ehcache.hibernate.regions.EhcacheTransactionalDataRegion.put(EhcacheTransactionalDataRegion.java:127)
      at net.sf.ehcache.hibernate.strategy.NonStrictReadWriteEhcacheEntityRegionAccessStrategy.putFromLoad(NonStrictReadWriteEhcacheEntityRegionAccessStrategy.java:66)
      at net.sf.ehcache.hibernate.nonstop.NonstopAwareEntityRegionAccessStrategy.putFromLoad(NonstopAwareEntityRegionAccessStrategy.java:180)
      at org.hibernate.engine.TwoPhaseLoad.initializeEntity(TwoPhaseLoad.java:180)
      at org.hibernate.loader.Loader.initializeEntitiesAndCollections(Loader.java:898)
      at org.hibernate.loader.Loader.doQuery(Loader.java:773)
      at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:270)
      at org.hibernate.loader.Loader.loadEntity(Loader.java:1953)
      at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:86)
      at org.hibernate.loader.entity.AbstractEntityLoader.load(AbstractEntityLoader.java:76)
      at org.hibernate.persister.entity.AbstractEntityPersister.load(AbstractEntityPersister.java:3270)
      at org.hibernate.event.def.DefaultLoadEventListener.loadFromDatasource(DefaultLoadEventListener.java:496)
      at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:477)
      at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:227)
      at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:147)
      at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1080)
      at org.hibernate.impl.SessionImpl.immediateLoad(SessionImpl.java:1018)
      at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:176)
      at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:215)
      at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:191)
      at vyre.content.items.ItemInfo_$$_javassist_87.equals(ItemInfo_$$_javassist_87.java:-1)
      at org.hibernate.util.EqualsHelper.equals(EqualsHelper.java:33)
      at org.hibernate.type.AbstractType.isEqual(AbstractType.java:132)
      at org.hibernate.type.ComponentType.isEqual(ComponentType.java:153)
      at org.hibernate.cache.CacheKey.equals(CacheKey.java:79)
      at net.sf.ehcache.store.compound.Segment.containsKey(Segment.java:279)
      at net.sf.ehcache.store.compound.CompoundStore.containsKey(CompoundStore.java:353)
      at net.sf.ehcache.store.compound.impl.MemoryOnlyStore.containsKeyInMemory(MemoryOnlyStore.java:121)
      at net.sf.ehcache.Cache.searchInStoreWithStats(Cache.java:1884)
      at net.sf.ehcache.Cache.get(Cache.java:1549)
      at net.sf.ehcache.constructs.EhcacheDecoratorAdapter.get(EhcacheDecoratorAdapter.java:75)
      at net.sf.ehcache.hibernate.regions.EhcacheTransactionalDataRegion.get(EhcacheTransactionalDataRegion.java:105)
      at net.sf.ehcache.hibernate.strategy.NonStrictReadWriteEhcacheEntityRegionAccessStrategy.get(NonStrictReadWriteEhcacheEntityRegionAccessStrategy.java:55)
      at net.sf.ehcache.hibernate.nonstop.NonstopAwareEntityRegionAccessStrategy.get(NonstopAwareEntityRegionAccessStrategy.java:122)
      at org.hibernate.event.def.DefaultLoadEventListener.loadFromSecondLevelCache(DefaultLoadEventListener.java:586)
      at org.hibernate.event.def.DefaultLoadEventListener.doLoad(DefaultLoadEventListener.java:459)
      at org.hibernate.event.def.DefaultLoadEventListener.load(DefaultLoadEventListener.java:227)
      at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:147)
      at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1080)
      at org.hibernate.impl.SessionImpl.immediateLoad(SessionImpl.java:1018)
      at org.hibernate.proxy.AbstractLazyInitializer.initialize(AbstractLazyInitializer.java:176)
      at org.hibernate.proxy.AbstractLazyInitializer.getImplementation(AbstractLazyInitializer.java:215)
      at org.hibernate.proxy.pojo.javassist.JavassistLazyInitializer.invoke(JavassistLazyInitializer.java:191)
      at vyre.content.items.Item_$$_javassist_102.getName(Item_$$_javassist_102.java:-1)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-1)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:597)
      at org.apache.velocity.runtime.parser.node.PropertyExecutor.execute(PropertyExecutor.java:142)
      at org.apache.velocity.util.introspection.UberspectImpl$VelGetterImpl.invoke(UberspectImpl.java:533)
      at org.apache.velocity.runtime.parser.node.ASTIdentifier.execute(ASTIdentifier.java:198)
      at org.apache.velocity.runtime.parser.node.ASTReference.execute(ASTReference.java:252)
      at org.apache.velocity.runtime.parser.node.ASTReference.render(ASTReference.java:332)
      at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:336)
      at org.apache.velocity.runtime.RuntimeInstance.render(RuntimeInstance.java:1277)
      at org.apache.velocity.runtime.RuntimeInstance.evaluate(RuntimeInstance.java:1216)
      at org.apache.velocity.runtime.RuntimeInstance.evaluate(RuntimeInstance.java:1165)
      at org.apache.velocity.app.Velocity.evaluate(Velocity.java:191)
      at org.apache.jsp.WEB_002dINF.jsp.pub_005fmodule.taglibs.contentTemplate.search.itemLink_jsp._jspService(itemLink.jsp:36)

  (...another hundred or so irrelevant stack trace fragments skipped...)

This is how I understand the situation:

the stack bottom begins where Apache Velocity is doing an evaluation and is passed a Hibernate proxy object
this object is cached with <cache usage="nonstrict-read-write"/> and has a composite key
Hibernate attempts to get the entity from the cache
Hibernate/Ehcache checks equalness of the object (note: the "real" equals method is never executed)
the equal check returns false and the object is being loaded by the Hibernate
as soon as the load succeeds, the object is placed in the cache
deadlock?

The offending code snippet of looks like as follows:

net.sf.ehcache.store.compound.Segment.put(Segment.java:427) 

423 Element put(Object key, int hash, Element element, boolean onlyIfAbsent) { 
424    boolean installed = false; 
425    Object encoded = create(key, element); 
426 
427    writeLock().lock(); 
428    try { 
429       // ensure capacity 
430       if (count + 1 > threshold) {

I can access the encoded object but it looks like writeLock() has been acquired already and therefore the whole thread is stuck. This is where my powers end as I know very little about internals of Ehcache Segment.

Can anyone provide any tips on how to debug this further? Unfortunately, creating a little, self-consistent test case is not an option.

This has also been posted on Ehcache forums page.

Thanks in advance.

You can use jvisualvm to check when the lock appears - it should give you more ideas. By the way what platform do you run on? I fought similar problem a while ago (all threads blocked without an evidence of blocking thread) on AIX and it turned out to be due to missing patches — SirVaulterScoff, Oct 19 '11 at 06:02

score 8 · Accepted Answer · answered Oct 20 '11 at 15:47

Answering my own question just in case if someone else slips on this and the post in Ehcache forums will disappear.

The reason:
The reason for the deadlock was coming from the same thread, where an attempt to locate the object in the cache was done. In one of the bottom parts of the stack, Ehcache was doing readLock().lock() and writeLock().lock() on the same lock object. This is obviously a no-no.

Why did this happen? This happened because cache was loading another object as a side effect (another big no-no) and both objects ended in the same memory segment (and hence shared the same ReentrantLock). Hint: I use the same cache region as I did not want to specify capacities for hundreds of different entity types.

Why did this happen? Inadvertent loading on cache key lookup was happening because of my Hibernate mapping. The object (which was being looked up) had a composite key, referring to another object. Parts of that composite key have been used in the equals method and was causing that load. As a coincidence, loaded object was also attempted to be placed in the same cache segment - and causing a deadlock.

Lessons learned
Be extra careful with your Hibernate mappings. If you have a composite key, never use <key-many-to-one as this can lead to unpredictable results. I think many people do not realize this only because they place different types of objects into different cache regions, but inadvertent loads are nevertheless evil.

All credits go to Alex from Terracotta forums for helping me to find this out.

Why is it obviously a no-no to do readLock().lock() and writeLock().lock()? Doesn't a writer have to acquire both the read lock and write lock to block out both readers and other writers? — morten, Mar 05 '18 at 14:03
I didn't get what happened. I see a similar problem, but there is no Hibernate. I doo see that one cached method is calling another one, which seems strange, but I can't see how it can cause a deadlock. What was the problem with loading another object? How did it cause a deadlock? — morten, Mar 05 '18 at 14:06
Well, this was 6 or 7 years ago so I wouldn't be able to remember the details of it (nor I have the access to the source code any more), whether these were different threads or not. https://stackoverflow.com/a/37087262/7345 suggests that for different threads this would definitely cause a problem. — mindas, Mar 05 '18 at 14:46

score 0 · Answer 2 · answered Oct 18 '11 at 19:03

0

You could use JProfiler (there's a fully functional evaluation version) to look at the current locking graph. It supports java.util.concurrent locks and will tell you who has the lock and where it was acquired. With that information it will be easier to analyze the problem.

Disclaimer: My company develops JProfiler

answered Oct 18 '11 at 19:03

Ingo Kegel

46,523
10
71
102

Thanks kingo, but in this case the debugger is much more appropriate tool than the profiler. I found out that Ehcache acquires the read lock first and then attempts to acquire the write lock. The question is why does the Hibernate orchestrate it this way... – mindas Oct 19 '11 at 10:54

Debugging Hibernate/Ehcache deadlock

2 Answers2