10 Replies Latest reply on Apr 19, 2005 12:59 PM by ben.wang

    Cache deadlock problem when using TreeCache as 2LC for hiber

      I'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).




        • 1. Re: Cache deadlock problem when using TreeCache as 2LC for h

          This is serious problem if it is from cache. But I don't get what are you trying to say in the last couple sentences? And the log output also doesn't make sense to me either.

          Can you elaborate more? Also, do you think you can create a JUnit test case to see if you can reproduce purly from JBossCache? I.e., no servlet or Hibernate involved?

          -Ben

          • 2. Re: Cache deadlock problem when using TreeCache as 2LC for h
            belaban

            The problem is concurrent access to the same data from multiple transactions. Since we're using pessimistic locking in JBossCache, some of the transactions will time out trying to acquire locks held by other transactions.
            Until we implement optimistic locking, here's what you can do to work around this:
            - Commit the TX after each load(). Essentially a non-solution b/c you're discarding the Hibernate first-level cache every time
            - Use a different isolation level in JBossCache: instead of REP_READ use READ_UNCOMMITTED. This should be fine when you can accept dirty reads. Otherwise go to READ_COMMITTED.

            • 3. Re: Cache deadlock problem when using TreeCache as 2LC for h

              Neither READ_COMMITED nor READ_UNCOMMITED help, only NONE which is inappropriate.

              I do not claim it's cache's bug, but it appears to be some design issue.

              Let me explain. Suppose you have some read-only entity which is frequently used through application. This is exactly where I expect to take advantage of cache, right?
              I'm using hibernate but even without hibernate scenario is the same:

              Entity getEntity(PK entityPK){
               if(cache.exists(entityPK)){
               return (Entity)cache.get(entityPK);
               } else {
               Entity entity = (Entity)storage.load(entityPK);
               cache.put(entity); // write lock here
               return entity;
               }
              


              you'll do it yourself or O-R mapping tool (eg hibernate) will do it for you if you configured it to use TreeCache as 2nd level cache.

              In any application there are plenty of read-only entites which are the first candidates to caching.
              They are accessed in random order (should be no problem since they are read-only)
              BUT, ANY read access to that entity can cause write to the cache (if entity never been read or get evicted from cache) and therefore require write lock.
              So, running into deadlock becomes just a matter of time.

              In my example (in first post) I intentionally requesting that entities in different order and put some delay into servlet to easily reproduce the issue.

              Again, I'm not claiming a bug in TreeCache. But since I'm considering this is very common scenario (everyone caching readonly entities, if you're using O-R mapping tool like hibernate you definitely want 2LC do it for you) I'm looking for any solution allowing me to concurrently access cached read-only entities without deadlocks.

              PS commit after each load definitely not a solution - it leaves you without transactions and brings you huge overhead instead.




              • 4. Re: Cache deadlock problem when using TreeCache as 2LC for h
                belaban

                So here's my understand how Hibernate uses the 2nd level cache (disclaimer: I'm not a Hibernate expert).
                And I haven't read the docs yet...

                - 1st level cache is per Session. This is an Object-level cache
                - 2nd level is per VM, shared by all Sessions. This is a row-based cache
                - When an object is loaded, the corresponding rows are loaded from the DB and added to the 2nd level cache. Assuming we use JBossCache, these will be replicated
                (not sure about this point though)
                - Then H creates the object in the session cache
                - On update (TX commit): H writes to the DB, modified the session cache and (I guess) invalidates the 2nd level cache. The invalidate is replicated across the cluster.

                So, if this is correct, the 2nd level cache (JBossCache) is only read-accessed when *any* session in a JVM loads an object for the first time (scope=TX). So the session object is valid until TX end.
                When an object is modified, at TX end, the object is written back to the DB and invalidated from the 2nd level cache across the cluster.

                So reads to JBossCache happen on object-load in any given H Session, writes happen on object-modification (at TX end).

                So this means that locks are acquired in JBossCache for all reads and writes for the duration of TXs. If you use REPEATABLE_READ for JBossCache, then we have r/w lock semantics, ie. concurrent reads are possible. However, if you have *one* write in a given TX, all other TXs are locked out until the writing TX commits.

                So in your case, if you had only reads, you'd be fine. However, there is one write, which causes other TXs to block. Can you idntify that write ? If you keep that write TX short, then subsequently, all read TXs should be able to acquire locks and proceed.

                So in your servlet code, if you only do load() methods, you should *never* run into lock acquisition problems.

                • 5. Re: Cache deadlock problem when using TreeCache as 2LC for h

                   

                  "bela@jboss.com" wrote:
                  So here's my understand how Hibernate uses the 2nd level cache (disclaimer: I'm not a Hibernate expert).
                  And I haven't read the docs yet...

                  - 1st level cache is per Session. This is an Object-level cache
                  - 2nd level is per VM, shared by all Sessions. This is a row-based cache
                  - When an object is loaded, the corresponding rows are loaded from the DB and added to the 2nd level cache. Assuming we use JBossCache, these will be replicated
                  (not sure about this point though)


                  Right. and this is the place where write to cache happens.

                  following hibernate log records show what happens while loading entity which is missed in cache:


                  14:59:10,338 DEBUG [SessionImpl] loading [test.TestEntity#1]
                  14:59:10,338 DEBUG [SessionImpl] attempting to resolve [test.TestEntity#1]
                  14:59:10,416 DEBUG [SessionImpl] object not resolved in any cache [test.TestEntity#1]
                  14:59:10,416 DEBUG [BatcherImpl] about to open: 0 open PreparedStatements, 0 open ResultSets
                  14:59:16,432 DEBUG [SQL] select testentity0_.id as id0_, testentity0_.value as value0_ from TEST_ENTITY testentity0_ where testentity0_.id=?
                  14:59:16,432 DEBUG [BatcherImpl] preparing statement
                  14:59:16,682 DEBUG [BatcherImpl] done closing: 0 open PreparedStatements, 0 open ResultSets
                  14:59:16,682 DEBUG [BatcherImpl] closing statement
                  14:59:16,682 DEBUG [SessionImpl] resolving associations for [test.TestEntity#1]
                  14:59:16,697 DEBUG [SessionImpl] adding entity to second-level cache [test.TestEntity#1]
                  14:59:16,729 DEBUG [SessionImpl] done materializing entity [test.TestEntity#1]


                  as you see "adding entity to second-level cache" happens just after reading entity from storage and this is the place where cache.put() called.

                  "bela@jboss.com" wrote:

                  So in your servlet code, if you only do load() methods, you should *never* run into lock acquisition problems.


                  In fact, doing only load() I do run into locking problem.


                  • 6. Re: Cache deadlock problem when using TreeCache as 2LC for h

                    Can you enable this in Hibernate to see if that solves the problem:

                    hibernate.cache.use_minimal_puts

                    Gavin and I have had a discussion on the potential problem. That, when using query cache, Hibernate will do a put on the JBossCache while retrieving from db. This can cause a long lock that resulting in TimeoutException.

                    If this were the case, we will need to provide a way to get around this.

                    -Ben

                    • 7. Re: Cache deadlock problem when using TreeCache as 2LC for h

                       

                      "ben.wang@jboss.com" wrote:
                      Can you enable this in Hibernate to see if that solves the problem:

                      hibernate.cache.use_minimal_puts

                      Gavin and I have had a discussion on the potential problem. That, when using query cache, Hibernate will do a put on the JBossCache while retrieving from db. This can cause a long lock that resulting in TimeoutException.

                      If this were the case, we will need to provide a way to get around this.

                      -Ben


                      Ben,

                      this solves the problem but of limied usage. use_minimal_puts works only for read-only entities, accounting this parameter applicable for the whole hibernate instance (not for particular entity) it is only useful when all your entities are read-only which is not true in most cases.

                      I'd make emphasis, that problem is for any entity, not only declared read-only. I'm expecting, that unless I change and save entity or load it "for update", loading of entity is equivalent of simple sql select and will not cause any locking problem.
                      For the moment, any read (hibernate's load()) can cause cache's put() (and therefore write lock) in case entity missed in cache.
                      The problem appears not only as the result of using query cache (as described in your previous post), but with any of hibernate entity cached in TreeCache.


                      • 8. Re: Cache deadlock problem when using TreeCache as 2LC for h

                        I understand your point. The solution is to provide an optimistic locking behavior of which Gavin and us have been discussed for a while. This feature has urgency now. :-)

                        Finally, if it is random deadlock (so your first example above won't work), it will simply timeout and rollback the tx. So another alternative for now is to reduce the LockAcquistionTimeout in JBossCache from default 15s to, say, 3 secs.

                        You will get occasional deply but only randomly, that's the theory.

                        Another point is that this is the problem when you use pessimistic locking under tx. Nothing to do with the cache itself.

                        -Ben

                        • 9. Re: Cache deadlock problem when using TreeCache as 2LC for h
                          milx

                          Hello
                          Just wondering; does this mean that I have to disable the cache for my project? I have (as everyone) concurrent access (admin and batch updates, combinded with customer read access) and had used a transactional cache for common entities. I keep getting timeouts upon concurrent access to these entities, under what seems to be a deadlock, as both threads stop. Using Hibernate 2.1 and Jboss 3.2 and JbossCache 1.2. Thanks a bunch.
                          Regards
                          Trygve

                          • 10. Re: Cache deadlock problem when using TreeCache as 2LC for h

                            Supposedly using Hibernate3.0 and JBossCache1.2.2 should resolve this. We have someone still reported that query cache is still problematic. So we are invetigating now.

                            -Ben