[Logo] Terracotta Discussion Forums
  [Search] Search   [Recent Topics] Recent Topics   [Members]  Member Listing   [Groups] Back to home page 
[Register] Register / 
[Login] Login 
[Expert]
Ehcache deadlock  XML
Forum Index -> Ehcache
Author Message
mindas

neo

Joined: 09/05/2011 05:42:08
Messages: 7
Offline

Hi,

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 stack trace:

Code:
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...)
 


Some comments on how I understand this 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. 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? Unfortunately, creating a little, self-consistent test case is not an option.

Thanks in advance.
alexsnaps

consul

Joined: 06/19/2009 09:06:00
Messages: 482
Online

Hi,
Just looking at the stack trace here, it looks like a put to a segment happens while a resolving a get. This seems unusual. It looks to me like your Item entity is PK with a ItemInfo, is that correct ?
Could you post your mapping files for Item & ItemInfo (and class hierarchy, if applicable) ? I also wonder whether you have multiple entities mapped to the same cache region ? Not really important, but might exacerbate the issue.
I think this might be an issue with the mapping as, if I remember correctly, org.hibernate.type.Type#isEqual shouldn't result in hitting back to the database, which does seem to happen here (and hence populate the cache, while you are currently querying it).
Alex

Alex Snaps (Terracotta engineer)
mindas

neo

Joined: 09/05/2011 05:42:08
Messages: 7
Offline

Hi Alex,

Many thanks for looking at this!

You are indeed right, Item has a composite key to ItemInfo, the mapping is roughly as follows:

Code:
<hibernate-mapping>
     <class name="ItemInfo" table="item_info">
         <cache usage="nonstrict-read-write"/>
 
         <id name="id" length="30">...</id>
         ...
     </class>
 </hibernate-mapping>
 
 <hibernate-mapping>
     <class name="Item" table="item">
         <cache usage="nonstrict-read-write"/>
 
         <composite-id>
             <key-many-to-one name="itemInfo" column="item_id" lazy="false"/>
             <key-property name="version"/>
         </composite-id>
          ...
     </class>
 </hibernate-mapping>
 


In other words, ItemInfo is a base object and it contains many Items which contain version-specific data of the base. Item is identified via id of ItemInfo (foreign key) and version of itself (simple integer).

> whether you have multiple entities mapped to the same cache region ?
I think I am, as I am using this advice:
http://stackoverflow.com/questions/4452242/specifying-global-ehcache-capacity
tl;dr reasoning is that I don't want to end up manually specifying different capacities for all my regions (100+ of different entity types). I rather want them to be fighting for cache survival - if a certain object is hit more frequently it should have better survival chances, regardless of its type.

I have also found this topic on StackOverflow which 100% corresponds to my case:
http://stackoverflow.com/questions/5225617/hibernate-custom-proxy-generator-stop-equals-from-initializing-a-lazy-proxy
Like the SO OP, I also have:
- equals methods overridden which only checks the ids of the objects (Item::equals checks versions + ids of corresponding ItemInfos)
- using Javassist
- just before the deadlock happens, I always hit my own overridden ItemInfo::equals (which returns true).

This kind of brings to the question on why Hibernate is initializing objects already sitting in the cache? Surely if objects are in the cache, they should be initialized already, otherwise what is the point of caching them?
alexsnaps

consul

Joined: 06/19/2009 09:06:00
Messages: 482
Online

Well, the cache doesn't hold entities, but dehydrated representations of your entity instances. What happens is that, since your Item.equals() method does compare the PK, it looks like it does load one ItemInfo from the database and puts it in the cache.
Now since you share a single cache for all your regions, you do end up more easily facing that deadlock. I believe this is the only thread locked up, so that is probably trying to upgrade a read lock to a write one.
Chances are that id you'd map your ItemInfo as a Custom type, which then you'd also have to implement UserType#equals(Object, Object), so that it wouldn't require to instantiate the instance itself (the equals is to be performed to lookup the CacheKey in the Cache).
I'd try to map ItemInfo as that, doing all the extra work, so that comparison can be made on the "raw representation" of an ItemInfo.
Another work around would be, if I'm not mistaken, to use a dedicated Cache for ItemInfo, rather than to use a single Cache for all.

Alex Snaps (Terracotta engineer)
mindas

neo

Joined: 09/05/2011 05:42:08
Messages: 7
Offline

Hi Alex,

You were absolutely right. The mapping I had was loading ItemInfo on request in order to get Item.id (Item.id was a part of Item.equals() check). Phew!

I have redone the mapping and the loading-by-side-effect seems to be gone.

<general-rant>
This is scary stuff... took me absolute ages to understand what's going on, absolute ages to get it redone (still working on it), and will probably take ages to test and cherry-pick all the bugs as changes like these are always ground shattering. I am not saying I blame Ehcache but we only got this issue because we are switching from OSCache. I keep thinking that if Ehcache was using atomic/non-blocking approach, this problem would have never surfaced (I refer to Cliff Click's NBHM). Is this anything you guys are looking at implementing in the future?
</general-rant>

Huge thanks again for your support!
alexsnaps

consul

Joined: 06/19/2009 09:06:00
Messages: 482
Online

We'll always try to make the product as fast as possible, as long as correctness is ensured. In this particular case the locking itself isn't really the issue, but rather the Read to Write Lock upgrade.
But on a more OSCache related note, ehcache 2.5 (currently in beta) introduces CacheManager level resource management. You're now able to configure a CacheManager to use a maximum of say 500MB of the local heap.
You can read more on this here: http://www.ehcache.org/documentation/user-guide/configuration#memory-based-cache-sizing-ehcache-25-and-higher
While the Hibernate region factory will keep on creating a dedicated cache per region, you'll be able to decide how my memory all these caches use. The CacheManager will be the one choosing eviction based on the current access patterns to your caches. While the measurement does come at a cost, we believe it makes tuning sizes much easier, not only for the whole VM resource management, but also in tuning cache sizes amongst each other.

Alex Snaps (Terracotta engineer)
 
Forum Index -> Ehcache
Go to:   
Powered by JForum 2.1.7 © JForum Team