Cache deadlock problem when using TreeCache as 2LC for hiber
octopus Jan 26, 2005 2:19 PMI'm not sure whether it is problem of cache, hibernate or my design. Please give me an advise if there's a well-known pattern to solve this.
Suppose I have an entity with two props - key and value mapped to a table with two fields.
<hibernate-mapping> <class name="test.TestEntity" table="TEST_ENTITY"> <cache usage="transactional"/> <id name="id" type="int" > <generator class="assigned"/> </id> <property name="value" type="int"/> </class> </hibernate-mapping>
Suppose I have a servlet which prints values for keys passed as parameter. (like /servletName?keyList=1,2,3,4)
Servlet looks like
void service(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException { StringTokenizer st = new StringTokenizer(request.getParameter("keyList"), ","); UserTransaction utx; try { utx = (UserTransaction)new InitialContext().lookup("UserTransaction"); utx.begin(); Session session = HibernateContext.getSession("java:/hibernate/SessionFactory"); while(st.hasMoreTokens()){ Integer id = new Integer(st.nextToken()); System.out.println(""+Thread.currentThread()+" loading "+id); session.load(TestEntity.class, id); Thread.sleep(1000); } utx.commit(); } catch (Exception e) { e.printStackTrace(); } }
If I request simultaneously following url's:
..../servletName?keyList=1,2,3,4,5,6,7,8,9,10
and
..../servletName?keyList=10,9,8,7,6,5,4,3,2,1
I hava 100% chance to get a deadlock.
20:06:29,588 INFO [STDOUT] Thread[http-0.0.0.0-8180-Processor25,5,jboss] loading 1
20:06:31,635 INFO [STDOUT] Thread[http-0.0.0.0-8180-Processor24,5,jboss] loading 10
20:06:37,807 INFO [STDOUT] Thread[http-0.0.0.0-8180-Processor25,5,jboss] loading 2
20:06:39,041 INFO [STDOUT] Thread[http-0.0.0.0-8180-Processor25,5,jboss] loading 3
20:06:40,197 INFO [STDOUT] Thread[http-0.0.0.0-8180-Processor25,5,jboss] loading 4
20:06:41,619 INFO [STDOUT] Thread[http-0.0.0.0-8180-Processor25,5,jboss] loading 5
20:06:42,760 INFO [STDOUT] Thread[http-0.0.0.0-8180-Processor25,5,jboss] loading 6
20:06:43,057 INFO [STDOUT] Thread[http-0.0.0.0-8180-Processor24,5,jboss] loading 9
20:06:43,901 INFO [STDOUT] Thread[http-0.0.0.0-8180-Processor25,5,jboss] loading 7
20:06:44,229 INFO [STDOUT] Thread[http-0.0.0.0-8180-Processor24,5,jboss] loading 8
20:06:45,119 INFO [STDOUT] Thread[http-0.0.0.0-8180-Processor25,5,jboss] loading 8
20:06:45,401 INFO [STDOUT] Thread[http-0.0.0.0-8180-Processor24,5,jboss] loading 7
20:07:00,135 ERROR [IdentityLock] read lock for //hibernate/test/TestEntity/8 could not be acquired after 15000 ms. Lock
map ownership Read lock owners: []
Write lock owner: <null>:2
(caller=<null>:1)
20:07:00,166 INFO [STDOUT] net.sf.hibernate.cache.CacheException: org.jboss.cache.lock.TimeoutException: lock for //hibe
rnate/test/TestEntity/8 could not be acquired after 15000ms. Lock map ownership Read lock owners: []
Write lock owner: <null>:2
at net.sf.hibernate.cache.TreeCache.get(TreeCache.java:61)
at net.sf.hibernate.cache.TransactionalCache.get(TransactionalCache.java:29)
at net.sf.hibernate.impl.SessionImpl.doLoad(SessionImpl.java:2121)
at net.sf.hibernate.impl.SessionImpl.doLoadByClass(SessionImpl.java:2000)
at net.sf.hibernate.impl.SessionImpl.load(SessionImpl.java:1929)
at test.TestCacheLockServlet.service(TestCacheLockServlet.java:57)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:75)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:214)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.StandardContextValve.invokeInternal(StandardContextValve.java:198)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:152)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:66)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:162)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:118)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:535)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:929)
at org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:160)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:799)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:705)
at org.apache.tomcat.util.net.TcpWorkerThread.runIt(PoolTcpEndpoint.java:577)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683)
at java.lang.Thread.run(Thread.java:595)
Caused by: org.jboss.cache.lock.TimeoutException: lock for //hibernate/test/TestEntity/8 could not be acquired after 1500
0ms. Lock map ownership Read lock owners: []
Write lock owner: <null>:2
at org.jboss.cache.lock.IdentityLock.acquireReadLock(IdentityLock.java:218)
at org.jboss.cache.Node.acquireReadLock(Node.java:418)
at org.jboss.cache.Node.acquire(Node.java:399)
at org.jboss.cache.interceptors.LockInterceptor.lock(LockInterceptor.java:202)
at org.jboss.cache.interceptors.LockInterceptor.invoke(LockInterceptor.java:144)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:40)
at org.jboss.cache.interceptors.CreateIfNotExistsInterceptor.invoke(CreateIfNotExistsInterceptor.java:50)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:40)
at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:35)
at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:2978)
at org.jboss.cache.TreeCache.get(TreeCache.java:1509)
at org.jboss.cache.TreeCache.get(TreeCache.java:1493)
at net.sf.hibernate.cache.TreeCache.get(TreeCache.java:58)
... 39 more
20:07:00,401 ERROR [IdentityLock] read lock for //hibernate/test/TestEntity/7 could not be acquired after 15000 ms. Lock
map ownership Read lock owners: []
Write lock owner: <null>:1
(caller=<null>:2)
20:07:00,416 INFO [STDOUT] net.sf.hibernate.cache.CacheException: org.jboss.cache.lock.TimeoutException: lock for //hibe
rnate/test/TestEntity/7 could not be acquired after 15000ms. Lock map ownership Read lock owners: []
Write lock owner: <null>:1
at net.sf.hibernate.cache.TreeCache.get(TreeCache.java:61)
at net.sf.hibernate.cache.TransactionalCache.get(TransactionalCache.java:29)
at net.sf.hibernate.impl.SessionImpl.doLoad(SessionImpl.java:2121)
at net.sf.hibernate.impl.SessionImpl.doLoadByClass(SessionImpl.java:2000)
at net.sf.hibernate.impl.SessionImpl.load(SessionImpl.java:1929)
at test.TestCacheLockServlet.service(TestCacheLockServlet.java:57)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:810)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:237)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:75)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:186)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:157)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:214)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.StandardContextValve.invokeInternal(StandardContextValve.java:198)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:152)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:66)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:162)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:137)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:118)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:535)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:102)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.core.StandardValveContext.invokeNext(StandardValveContext.java:104)
at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:520)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:929)
at org.apache.coyote.tomcat5.CoyoteAdapter.service(CoyoteAdapter.java:160)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:799)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:705)
at org.apache.tomcat.util.net.TcpWorkerThread.runIt(PoolTcpEndpoint.java:577)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:683)
at java.lang.Thread.run(Thread.java:595)
Caused by: org.jboss.cache.lock.TimeoutException: lock for //hibernate/test/TestEntity/7 could not be acquired after 1500
0ms. Lock map ownership Read lock owners: []
Write lock owner: <null>:1
at org.jboss.cache.lock.IdentityLock.acquireReadLock(IdentityLock.java:218)
at org.jboss.cache.Node.acquireReadLock(Node.java:418)
at org.jboss.cache.Node.acquire(Node.java:399)
at org.jboss.cache.interceptors.LockInterceptor.lock(LockInterceptor.java:202)
at org.jboss.cache.interceptors.LockInterceptor.invoke(LockInterceptor.java:144)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:40)
at org.jboss.cache.interceptors.CreateIfNotExistsInterceptor.invoke(CreateIfNotExistsInterceptor.java:50)
at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:40)
at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:35)
at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:2978)
at org.jboss.cache.TreeCache.get(TreeCache.java:1509)
at org.jboss.cache.TreeCache.get(TreeCache.java:1493)
at net.sf.hibernate.cache.TreeCache.get(TreeCache.java:58)
... 39 more
The thing is: when I try to read an entity which is missing in cache it is loaded from storage and get written to cache leaving a write lock.
As soon as entities get evicted from cache, ANY "read" of entity can become "write" to cache requiring write lock.
My question is: is it possible to avoid deadlocks when reading entities in random order (very common scenario).