EHC ❯ Deadlock using ehcache as Hibernate second level cache

• Type: Bug
• Status: Closed
• Priority: 2 Major
• Resolution: Duplicate
• Component/s:
• Labels:

• Assignee: alexsnaps
• Reporter: xpoinsar
• Created: February 03, 2012
• Votes: 0
• Watchers: 1
• Updated:

  July 27, 2012
• Resolved:

  February 09, 2012

Attachments

• xpoinsar (34.00 k) text/plain ThreadDumpLock.txt

Description

We encountered a deadlock involving 3 threads. Here is an extract of the thread dump.

“http-8080-exec-67”: at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006d3891148> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync) 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.doAcquireShared(AbstractQueuedSynchronizer.java:941) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1261) at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:594) at net.sf.ehcache.store.chm.SelectableConcurrentHashMap$MemoryStoreSegment.get(SelectableConcurrentHashMap.java:530) at net.sf.ehcache.store.chm.SelectableConcurrentHashMap$MemoryStoreSegment.get(SelectableConcurrentHashMap.java:262) at net.sf.ehcache.store.chm.ConcurrentHashMap.get(ConcurrentHashMap.java:776) at net.sf.ehcache.store.MemoryStore.get(MemoryStore.java:311) at net.sf.ehcache.store.MemoryStore.getQuiet(MemoryStore.java:332) at net.sf.ehcache.store.FrontEndCacheTier.getQuiet(FrontEndCacheTier.java:196) at net.sf.ehcache.Cache.searchInStoreWithoutStats(Cache.java:2101) at net.sf.ehcache.Cache.get(Cache.java:1630) at net.sf.ehcache.hibernate.regions.EhcacheTransactionalDataRegion.get(EhcacheTransactionalDataRegion.java:106) at net.sf.ehcache.hibernate.strategy.NonStrictReadWriteEhcacheEntityRegionAccessStrategy.get(NonStrictReadWriteEhcacheEntityRegionAccessStrategy.java:52) at net.sf.ehcache.hibernate.nonstop.NonstopAwareEntityRegionAccessStrategy.get(NonstopAwareEntityRegionAccessStrategy.java:122) at org.hibernate.event.def.DefaultLoadEventListener.loadFromSecondLevelCache(DefaultLoadEventListener.java:587) 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.proxyOrLoad(DefaultLoadEventListener.java:269) at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152) at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1090) at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1038) at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:630) at org.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:236) at org.hibernate.cache.StandardQueryCache.get(StandardQueryCache.java:153) at org.hibernate.loader.Loader.getResultFromQueryCache(Loader.java:2366) at org.hibernate.loader.Loader.listUsingQueryCache(Loader.java:2309) at org.hibernate.loader.Loader.list(Loader.java:2268) at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:459) at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:365) at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196) at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1268) at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102) at org.hibernate.impl.AbstractQueryImpl.uniqueResult(AbstractQueryImpl.java:890) at com.openpricer.ac.UserManagement.internal.strategy.GetUserStrategy.execute(GetUserStrategy.java:43) at com.openpricer.ac.UserManagement.ejb.UserManagementInterfaceBean.getUser(UserManagementInterfaceBean.java:96) at com.openpricer.common.webapp.helpers.UserHelper.getUser(UserHelper.java:100) at com.openpricer.common.webapp.helpers.UserHelper.hasPrivilege(UserHelper.java:299) at com.openpricer.contractpricer.webapp.MainPageAction.execute(MainPageAction.java:34) at org.apache.struts.chain.commands.servlet.ExecuteAction.execute(ExecuteAction.java:58) at org.apache.struts.chain.commands.AbstractExecuteAction.execute(AbstractExecuteAction.java:67) at org.apache.struts.chain.commands.ActionCommandBase.execute(ActionCommandBase.java:51) at org.apache.commons.chain.impl.ChainBase.execute(ChainBase.java:191) at org.apache.commons.chain.generic.LookupCommand.execute(LookupCommand.java:305) at org.apache.commons.chain.impl.ChainBase.execute(ChainBase.java:191) at org.apache.struts.chain.ComposableRequestProcessor.process(ComposableRequestProcessor.java:283) at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1913) at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:449) at javax.servlet.http.HttpServlet.service(HttpServlet.java:617) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:646) at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:436) at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:374) at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:302) at org.apache.jasper.runtime.PageContextImpl.doForward(PageContextImpl.java:709) at org.apache.jasper.runtime.PageContextImpl.forward(PageContextImpl.java:680) at org.apache.jsp.index_jsp._jspService(Unknown Source) at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at com.openpricer.common.hibernate.Persistance.doFilter(Persistance.java:99) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:563) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298) at org.apache.coyote.http11.Http11NioProcessor.process(Http11NioProcessor.java:889) at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:732) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:2262) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) “Timer-12”: at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006d3b17ea0> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync) 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.concurrent.ReadWriteLockSync.lock(ReadWriteLockSync.java:50) at net.sf.ehcache.hibernate.regions.EhcacheTransactionalDataRegion.readLock(EhcacheTransactionalDataRegion.java:221) at net.sf.ehcache.hibernate.strategy.AbstractReadWriteEhcacheAccessStrategy.readLockIfNeeded(AbstractReadWriteEhcacheAccessStrategy.java:174) at net.sf.ehcache.hibernate.strategy.AbstractReadWriteEhcacheAccessStrategy.get(AbstractReadWriteEhcacheAccessStrategy.java:63) at net.sf.ehcache.hibernate.nonstop.NonstopAwareEntityRegionAccessStrategy.get(NonstopAwareEntityRegionAccessStrategy.java:122) at org.hibernate.event.def.DefaultLoadEventListener.loadFromSecondLevelCache(DefaultLoadEventListener.java:587) 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:1090) at org.hibernate.impl.SessionImpl.immediateLoad(SessionImpl.java:1026) 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:190) at com.openpricer.ac.tasks.is.PTask_\(\_javassist\_45.setDetailedStatus(PTask\_\)_javassist_45.java) at com.openpricer.ac.tasks.internal.strategy.SetTaskDetailedStatusStrategy.execute(SetTaskDetailedStatusStrategy.java:30) at com.openpricer.ac.tasks.ejb.TasksManagementBean.setTaskDetailedStatus(TasksManagementBean.java:392) at com.openpricer.ac.tasks.loader.DataLoadingTask.processDataLoadingTask(DataLoadingTask.java:859) at com.openpricer.ac.tasks.loader.DataLoadingTask.methodToRun(DataLoadingTask.java:316) at com.openpricer.ac.tasks.helpers.BaseTask.opRun(BaseTask.java:258) at com.openpricer.common.tasks.OPTimerTask.run(OPTimerTask.java:30) at java.util.TimerThread.mainLoop(Timer.java:512) at java.util.TimerThread.run(Timer.java:462) “Thread-31”: at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006d400fc10> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync) 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.doAcquireShared(AbstractQueuedSynchronizer.java:941) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1261) at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:594) at net.sf.ehcache.store.chm.SelectableConcurrentHashMap$MemoryStoreSegment.get(SelectableConcurrentHashMap.java:530) at net.sf.ehcache.store.chm.SelectableConcurrentHashMap$MemoryStoreSegment.get(SelectableConcurrentHashMap.java:262) at net.sf.ehcache.store.chm.ConcurrentHashMap.get(ConcurrentHashMap.java:776) at net.sf.ehcache.store.MemoryStore.get(MemoryStore.java:311) at net.sf.ehcache.store.MemoryStore.getQuiet(MemoryStore.java:332) at net.sf.ehcache.store.FrontEndCacheTier.getQuiet(FrontEndCacheTier.java:196) at net.sf.ehcache.Cache.searchInStoreWithoutStats(Cache.java:2101) at net.sf.ehcache.Cache.get(Cache.java:1630) at net.sf.ehcache.hibernate.regions.EhcacheTransactionalDataRegion.get(EhcacheTransactionalDataRegion.java:106) at net.sf.ehcache.hibernate.strategy.AbstractReadWriteEhcacheAccessStrategy.get(AbstractReadWriteEhcacheAccessStrategy.java:65) at net.sf.ehcache.hibernate.nonstop.NonstopAwareEntityRegionAccessStrategy.get(NonstopAwareEntityRegionAccessStrategy.java:122) at org.hibernate.event.def.DefaultLoadEventListener.loadFromSecondLevelCache(DefaultLoadEventListener.java:587) 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.proxyOrLoad(DefaultLoadEventListener.java:285) at org.hibernate.event.def.DefaultLoadEventListener.onLoad(DefaultLoadEventListener.java:152) at org.hibernate.impl.SessionImpl.fireLoad(SessionImpl.java:1090) at org.hibernate.impl.SessionImpl.internalLoad(SessionImpl.java:1038) at org.hibernate.type.EntityType.resolveIdentifier(EntityType.java:630) at org.hibernate.type.ManyToOneType.assemble(ManyToOneType.java:236) at org.hibernate.cache.StandardQueryCache.get(StandardQueryCache.java:153) at org.hibernate.loader.Loader.getResultFromQueryCache(Loader.java:2366) at org.hibernate.loader.Loader.listUsingQueryCache(Loader.java:2309) at org.hibernate.loader.Loader.list(Loader.java:2268) at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:459) at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:365) at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196) at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1268) at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102) at com.openpricer.ac.tasks.internal.strategy.GetAllUnreadTasksFromUserStrategy.execute(GetAllUnreadTasksFromUserStrategy.java:38) at com.openpricer.ac.tasks.ejb.TasksManagementBean.getAllUnreadTasksFromUser(TasksManagementBean.java:477) at com.openpricer.bc.tasks.webapp.TasksFeedbackServlet$TasksFeedback$1.run(TasksFeedbackServlet.java:235) at java.lang.Thread.run(Thread.java:662)

Found 1 deadlock.

Comments

Fiona OShea 2012-02-03

Alex can you take a look please?

Alexander Snaps 2012-02-07

It looks like a lookup in the QueryCache is triggering a load. This might be the issue. Are all the regions mapped to a single Cache ? Can you provide some mapping information related to this getUser call ? Also, seeing how this loading of the user is resolved would be interesting. Right now I suspect a mapping issue though… Trying to (in)validate the hypothesis.

Xavier Poinsard 2012-02-07

Regarding you question on regions, I am not sure. Where can I check this ?

The code in getUser is the following :

Query q = session.createQuery(“from PUser u where u.name = ?”); q.setString(0, argUserName); q.setCacheable(true); myUser = (PUser) q.uniqueResult();

The (simplified) mapping for PUser is :

SeqUsers</param> the user name</meta> manager user name for this user (overriding manager from user team)</meta> user's team</meta> user profiles</meta>

The relevant part of ehcache.xml are :

<cache
    name="org.hibernate.cache.StandardQueryCache"
    maxElementsInMemory="500000"
    eternal="false"
    overflowToDisk="true"/>          
    
<cache
    name="org.hibernate.cache.UpdateTimestampsCache"
    maxElementsInMemory="5000"
    eternal="true"
    overflowToDisk="false"/>  

With your remark regarding queryCache triggering a load, I think it’s possible since the User is referencing another User (his manager). When you say “this might be the issue”, does that mean that I should change the mapping or the issue is inside Hibernate or ehcache ?

Alexander Snaps 2012-02-07

It’s hard for me to actually point to the problem still. I did find a bug in the ReadWriteAccessStrategy that was locking the write lock when only the read one should suffice. But I can’t find any evidence that you are hitting this issue (or that it ever was an issue, but a performance one). Could you provide the entire thread dump and VM output when the deadlock occurred ? Did this happen in product or in dev ? Is this reproducible ? Could you provide a reproducible test-case ? All you mapping files (looks like the entities loaded on the non http threads are using different access strategies) and complete ehcache.xml would be useful, as well as VM, Hibernate & ehcache version.

If the last point is an issue to be posted here, you can mail them to me directly at : asnaps [at] terracotta [dot] org

Xavier Poinsard 2012-02-08

The full thread dump.

Xavier Poinsard 2012-02-08

It happened on a pre-preproduction box. It seems really difficult to reproduce. VM version : java version “1.6.0_24” Java(TM) SE Runtime Environment (build 1.6.0_24-b07) Java HotSpot(TM) 64-Bit Server VM (build 19.1-b02, mixed mode) Hibernate : 3.6.8 ehcache : 2.4.6 I am sending you directly the complete ehcache.xml and mapping.

I am able to have a reproducible deadlock situation, but this deadlock doesn’t seem to be detected by the VM.

Alexander Snaps 2012-02-08

Based on the attached stack trace you’re running ehcache 2.5 and not 2.4.3. If you are running 2.5.0, there is a bug around locking and pinning (see the FrontEndCacheTier.unpinAll(FrontEndCacheTier.java:91) method call of thread “http-8080-exec-2”). Upgrading to 2.5.1 should solve this. Now on the other issue you’ve encountered, was that using 2.5 or 2.4 ? I really need exact versions to be able to track this down…

Xavier Poinsard 2012-02-08

You are right, I am using by mistake 2.5.0 instead of 2.4.6. After upgrading to 2.5.1 or downgrading to 2.4.7, I can’t reproduce my reproducible test case. Should I stick to 2.4.7 for more safety or go on with 2.5.1 ?

Alexander Snaps 2012-02-08

2.5.1 should be fine now wrt Hibernate and does bring you new and interesting features. w/o changing anything, you’d already get to pinned elements for all softlock’ed entries when using Hibernate’s read-write lock strategy (which might mean little to you though). As far as this jira goes now though, I’ll let it up to you to close it or not… I still feel this deadlock that was identified by the VM might be an issue though. Do you know for sure what ehcache version you were running at that point ?

Xavier Poinsard 2012-02-08

Yes it was 2.5.0 : I checked directly in the jar in the Tomcat folder.

Alexander Snaps 2012-02-09

Was encountered in 2.5, and is fixed by EHC-903 in 2.5.1

Xavier Poinsard 2012-06-23

In fact, it is not blocked but deadly slow.

Xavier Poinsard 2012-06-23

sorry wrong issue