4 Replies Latest reply on Aug 22, 2007 11:37 AM by manik

    Unexpected (?) TimeoutException

    jacek187

      Could anybody tel me, why I got TimeoutException when 2 Threads are executing this code?

       for (int x = 0; x < 1000; x++) {
       tm.begin();
       System.out.println("R" + Thread.currentThread().getName());
       //inside transaction
       cache.remove("/a");
       System.out.println("AR" + Thread.currentThread().getName());
       tm.commit();
       //outside transaction
       System.out.println("P" + Thread.currentThread().getName());
       cache.putObject("/a/b/c/d", "text"+x);
       System.out.println("AP" + Thread.currentThread().getName());
       }
      


      Console Output:
      RThread:0
      RThread:1
      ARThread:1
      ARThread:0
      PThread:1
      PThread:0
      APThread:1
      RThread:1

      org.jboss.cache.lock.TimeoutException: failure acquiring lock: fqn=/a, caller=GlobalTransaction::3, lock=read owners=[GlobalTransaction::3], write owner=GlobalTransaction::5 (org.jboss.cache.lock.LockStrategyReadCommitted@d02b51)
      at org.jboss.cache.Node.acquire(Node.java:500)
      at org.jboss.cache.interceptors.PessimisticLockInterceptor.acquireNodeLock(PessimisticLockInterceptor.java:379)
      at org.jboss.cache.interceptors.PessimisticLockInterceptor.lock(PessimisticLockInterceptor.java:307)
      at
      (...)

      Complete code:
      package org.jboss.cache.aop;
      
      import java.util.ArrayList;
      import java.util.List;
      
      import javax.transaction.TransactionManager;
      
      import junit.framework.TestCase;
      
      import org.jboss.cache.DummyTransactionManagerLookup;
      import org.jboss.cache.TreeCache;
      import org.jboss.cache.lock.IsolationLevel;
      
      public class ConcurentPutRemoveTest extends TestCase {
      
       private TransactionManager tm;
      
       public ConcurentPutRemoveTest(String s) {
       super(s);
       }
      
       private PojoCache cache;
      
       protected void setUp() throws Exception {
       cache = new PojoCache();
       cache.setCacheMode(TreeCache.LOCAL);
       cache.setIsolationLevel(IsolationLevel.READ_COMMITTED);
       cache.setTransactionManagerLookup(new DummyTransactionManagerLookup());
       cache.setLockAcquisitionTimeout(10000);
       cache.create();
       cache.start();
       tm = cache.getTransactionManager();
       }
      
       protected void tearDown() throws Exception {
       super.tearDown();
       cache.stop();
       cache.destroy();
       }
      
       public void testLock() throws Exception {
       List<SeparateThread> threads = new ArrayList<SeparateThread>();
       for (int x = 0; x < 2; x++) {
       SeparateThread t = new SeparateThread(x);
       threads.add(t);
       t.start();
       }
       for (SeparateThread separateThread : threads) {
       separateThread.join();
       if (separateThread.getException() != null) {
       throw separateThread.getException();
       }
       }
      
       }
      
       private class SeparateThread extends Thread {
       Exception e = null;
      
       private int num = 0;
      
       public SeparateThread(int num) {
       this.num = num;
       }
      
       public Exception getException() {
       return e;
       }
      
       public void run() {
       Thread.currentThread().setName("Thread:" + num);
       try {
       for (int x = 0; x < 1000; x++) {
       tm.begin();
       System.out.println("R" + Thread.currentThread().getName());
       //inside transaction
       cache.remove("/a");
       System.out.println("AR" + Thread.currentThread().getName());
       tm.commit();
       //outside transaction
       System.out.println("P" + Thread.currentThread().getName());
       cache.putObject("/a/b/c/d", "text"+x);
       System.out.println("AP" + Thread.currentThread().getName());
       }
       } catch (Exception e) {
       this.e = e;
       }
       }
       }
      
      }
      


        • 1. Re: Unexpected (?) TimeoutException
          brian.stansberry

          Don't mix PojoCache API calls (putObject) and plain cache API calls (remove(String)) in this manner. Pick one or the other -- use removeObject(String) or put(String, Object, Object).

          • 2. Re: Unexpected (?) TimeoutException
            jason.greene

            Also this code is contending on locks, so with pessimistic locking its normal to see TimeoutExceptions, UpgradeException and so on.

            • 3. Re: Unexpected (?) TimeoutException
              jacek187

              Hi
              When i change to put/remove from TreeCache API I got .. different results
              Sometimes I got success.
              Sometimes I got NodeNotExistException - probably bug
              Sometimes I got ... infinitive loop. This is critical bug !!!!!! And this situation was observer in our production systems but until now I can;t prepare JUnit test to show this case.

              main loop looks now like:

               for (int x = 0; x < 1000; x++) {
               tm.begin();
               System.out.println("R" + Thread.currentThread().getName());
               //inside transaction
               cache.remove("/a");
               System.out.println("AR" + Thread.currentThread().getName());
               tm.commit();
               //outside transaction
               System.out.println("P" + Thread.currentThread().getName());
               cache.put("/a/b/c/d", "text"+x,"b");
               System.out.println("AP" + Thread.currentThread().getName());
               }
              


              The most critical bug is infinitive loop - sometimes this test never ends, CPU usage is 100%, and ThreadDumps shows, that one thread is still working in loop:
              PessimisticLockInterceptor, lines 173-178

               do
               {
               lock(fqn, ctx.getGlobalTransaction(), lock_type, recursive, zeroLockTimeout ? 0 : lock_timeout, createIfNotExists, storeLockedNode);
               }
               while(!cache.exists(fqn)); // keep trying until we have the lock (fixes concurrent remove())
              




              Some thread dumps

              Dump 1:

              "Thread:0" prio=6 tid=0x0ae49c48 nid=0x121c runnable [0x0b38f000..0x0b38fb68]
              at org.jboss.cache.interceptors.PessimisticLockInterceptor.recordNodeLock(PessimisticLockInterceptor.java:398)
              at org.jboss.cache.interceptors.PessimisticLockInterceptor.acquireNodeLock(PessimisticLockInterceptor.java:383)
              at org.jboss.cache.interceptors.PessimisticLockInterceptor.lock(PessimisticLockInterceptor.java:307)
              at org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:175)
              at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
              at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:32)
              at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
              at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:365)
              at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:160)
              at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
              at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:157)
              at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:5877)
              at org.jboss.cache.TreeCache.put(TreeCache.java:3847)
              at org.jboss.cache.TreeCache.put(TreeCache.java:3788)
              at org.jboss.cache.aop.ConcurentPutRemoveTest$SeparateThread.run(ConcurentPutRemoveTest.java:82)



              "main" prio=6 tid=0x003a7988 nid=0xbc0 in Object.wait() [0x0006f000..0x0006fc08]
              at java.lang.Object.wait(Native Method)
              - waiting on <0x02b50188> (a org.jboss.cache.aop.ConcurentPutRemoveTest$SeparateThread)
              at java.lang.Thread.join(Unknown Source)
              - locked <0x02b50188> (a org.jboss.cache.aop.ConcurentPutRemoveTest$SeparateThread)
              at java.lang.Thread.join(Unknown Source)
              at org.jboss.cache.aop.ConcurentPutRemoveTest.testLock(ConcurentPutRemoveTest.java:49)
              at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
              at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
              at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
              at java.lang.reflect.Method.invoke(Unknown Source)
              at junit.framework.TestCase.runTest(TestCase.java:154)
              at junit.framework.TestCase.runBare(TestCase.java:127)
              at junit.framework.TestResult$1.protect(TestResult.java:106)
              at junit.framework.TestResult.runProtected(TestResult.java:124)
              at junit.framework.TestResult.run(TestResult.java:109)
              at junit.framework.TestCase.run(TestCase.java:118)
              at junit.framework.TestSuite.runTest(TestSuite.java:208)
              at junit.framework.TestSuite.run(TestSuite.java:203)
              at org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:128)
              at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
              at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)
              at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)
              at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)
              at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)



              Dump 2 (makes 1 minute later)
              "Thread:0" prio=6 tid=0x0ae49c48 nid=0x121c runnable [0x0b38f000..0x0b38fb68]
              at org.jboss.cache.Node.isMarkedForRemoval(Node.java:690)
              at org.jboss.cache.TreeCache.findInternal(TreeCache.java:3714)
              at org.jboss.cache.TreeCache.exists(TreeCache.java:3694)
              at org.jboss.cache.interceptors.PessimisticLockInterceptor.invoke(PessimisticLockInterceptor.java:177)
              at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
              at org.jboss.cache.interceptors.UnlockInterceptor.invoke(UnlockInterceptor.java:32)
              at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
              at org.jboss.cache.interceptors.TxInterceptor.handleNonTxMethod(TxInterceptor.java:365)
              at org.jboss.cache.interceptors.TxInterceptor.invoke(TxInterceptor.java:160)
              at org.jboss.cache.interceptors.Interceptor.invoke(Interceptor.java:68)
              at org.jboss.cache.interceptors.CacheMgmtInterceptor.invoke(CacheMgmtInterceptor.java:157)
              at org.jboss.cache.TreeCache.invokeMethod(TreeCache.java:5877)
              at org.jboss.cache.TreeCache.put(TreeCache.java:3847)
              at org.jboss.cache.TreeCache.put(TreeCache.java:3788)
              at org.jboss.cache.aop.ConcurentPutRemoveTest$SeparateThread.run(ConcurentPutRemoveTest.java:82)




              Dumps shows that Thread 'Thread0' is now in endless looop.......



              Could anybody reproduce this error?

              • 4. Re: Unexpected (?) TimeoutException
                manik

                Thx for the tests, etc. in JBCACHE-1165