Uploaded image for project: 'JBoss Cache'
  1. JBoss Cache
  2. JBCACHE-1613

Lock TimeoutException when using a JTS transaction manager under load

    Details

    • Type: Bug
    • Status: Resolved (View Workflow)
    • Priority: Major
    • Resolution: Done
    • Affects Version/s: 3.2.8.GA
    • Fix Version/s: 3.2.9.GA
    • Component/s: Transactions
    • Labels:
      None
    • Steps to Reproduce:
      Hide

      Enable JTS:
      cd $JBOSS_HOME/docs/examples/transactions
      modify target.server.dir in build.xml to point to the correct profile
      ant jts

      Configure a cache using transactions, MVCC, and REPL_ASYNC (I have not tested whether modes other than REPL_ASYNC also trigger it)
      For instance, using the "timestamps-cache" after adding the following:

      <property name="transactionManagerLookupClass">org.jboss.cache.transaction.GenericTransactionManagerLookup</property>

      Enable TRACE logging for org.jboss.cache.lock.MVCCLockManager

      In multiple threads, run the following in a loop:

      tm.begin ();
      cache.put ( "/foo/bar", "foo", "bar" );
      tm.commit ();

      See attached JTSCache for a test case: new JTSCache().test();
      (I was able to reproduce the issue multiple times with 2 threads running 100 iterations each).

      Expected result:
      No errors. No IllegalMonitorStateException

      Actual result:
      java.lang.IllegalMonitorStateException logged at TRACE level from org.jboss.cache.lock.MVCCLockManager
      (which will also cause a TimeoutException if another thread is waiting on the same lock when it happens)

      Show
      Enable JTS: cd $JBOSS_HOME/docs/examples/transactions modify target.server.dir in build.xml to point to the correct profile ant jts Configure a cache using transactions, MVCC, and REPL_ASYNC (I have not tested whether modes other than REPL_ASYNC also trigger it) For instance, using the "timestamps-cache" after adding the following: <property name="transactionManagerLookupClass">org.jboss.cache.transaction.GenericTransactionManagerLookup</property> Enable TRACE logging for org.jboss.cache.lock.MVCCLockManager In multiple threads, run the following in a loop: tm.begin (); cache.put ( "/foo/bar", "foo", "bar" ); tm.commit (); See attached JTSCache for a test case: new JTSCache().test(); (I was able to reproduce the issue multiple times with 2 threads running 100 iterations each). Expected result: No errors. No IllegalMonitorStateException Actual result: java.lang.IllegalMonitorStateException logged at TRACE level from org.jboss.cache.lock.MVCCLockManager (which will also cause a TimeoutException if another thread is waiting on the same lock when it happens)
    • Affects:
      Release Notes

      Description

      After switching to JTS for transactions, "random" lock timeouts occur:

      org.jboss.cache.lock.TimeoutException: Unable to acquire lock on Fqn [/foo] after [15000] milliseconds for requestor [GlobalTransaction:<10.1.2.3:12345>:5]! Lock held by [null]
      at org.jboss.cache.mvcc.MVCCNodeHelper.acquireLock(MVCCNodeHelper.java:157)

      The actual cause is only logged at TRACE level:

      TRACE [org.jboss.cache.lock.MVCCLockManager] (RequestProcessor-97) Attempting to unlock /foo
      TRACE [org.jboss.cache.lock.MVCCLockManager] (RequestProcessor-97) Caught exception and ignoring.
      java.lang.IllegalMonitorStateException: org.jboss.cache.util.concurrent.locks.OwnableReentrantLock@4d93ddfa[State = 1, empty queue][Locked by GlobalTransaction:<10.1.2.3:12345>:4]
      at org.jboss.cache.util.concurrent.locks.OwnableReentrantLock.tryRelease(OwnableReentrantLock.java:139)
      at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1239)
      at org.jboss.cache.util.concurrent.locks.OwnableReentrantLock.unlock(OwnableReentrantLock.java:105)
      at org.jboss.cache.util.concurrent.locks.PerElementLockContainer.releaseLock(PerElementLockContainer.java:112)
      at org.jboss.cache.lock.MVCCLockManager.unlock(MVCCLockManager.java:147)
      at org.jboss.cache.interceptors.MVCCLockingInterceptor.cleanupLocks(MVCCLockingInterceptor.java:375)
      at org.jboss.cache.interceptors.MVCCLockingInterceptor.transactionalCleanup(MVCCLockingInterceptor.java:400)
      at org.jboss.cache.interceptors.MVCCLockingInterceptor.handlePrepareCommand(MVCCLockingInterceptor.java:332)
      ...

      The root cause is that JTS commits transactions in a different thread than the one calling commit.
      Under load, it even uses different threads for each call during the same transaction commit (beforeCompletion/afterCompletion).

      JBoss Cache stores some data in ThreadLocals, and when different threads call beforeCompletion and afterCompletion for the same transaction,
      it causes it to mix the data between the transactions causing data corruption.

      Particularly the "ctx = invocationContextContainer.get();" calls in org.jboss.cache.interceptors.TxInterceptor beforeCompletion and afterCompletion.

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

                People

                • Assignee:
                  dereed Dennis Reed
                  Reporter:
                  dereed Dennis Reed
                • Votes:
                  0 Vote for this issue
                  Watchers:
                  1 Start watching this issue

                  Dates

                  • Created:
                    Updated:
                    Resolved: