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:
<cache usage="nonstrict-read-write"/>
and has a composite key equals
method is never executed) 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.
Hibernate Second Level cache providers include EHCache and Infinispan, but EHCache is more popular and we will use it for our example project. However before we move to our project, we should know different strategies for caching an object.
Ehcache can be configured in two ways: The first way is through Java POJO where all configuration parameters are configured through Ehcache API. The second way is configuration through XML file where we can configure Ehcache according to provided schema definition.
Ehcache is a standards-based caching API that is used by Integration Server. Caching enables an application to fetch frequently used data from memory (or other nearby resource) rather than having to retrieve it from a database or other back-end system each time the data is needed.
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.
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With