[jbosscache-issues] [JBoss JIRA] (JBCACHE-1613) Lock TimeoutException when using a JTS transaction manager under load

[Dennis Reed (JIRA)]

     [ https://issues.jboss.org/browse/JBCACHE-1613?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Dennis Reed updated JBCACHE-1613:
---------------------------------

    Steps to Reproduce: 
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)


  was:
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>

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

Actual result:
org.jboss.cache.lock.TimeoutException errors
Possibly other errors, such as "ERROR [TxInterceptor] Transaction has a null transaction entry - beforeCompletion() will fail."


    
> Lock TimeoutException when using a JTS transaction manager under load
> ---------------------------------------------------------------------
>
>                 Key: JBCACHE-1613
>                 URL: https://issues.jboss.org/browse/JBCACHE-1613
>             Project: JBoss Cache
>          Issue Type: Bug
>      Security Level: Public(Everyone can see) 
>          Components: Transactions
>    Affects Versions: 3.2.8.GA
>            Reporter: Dennis Reed
>            Assignee: Dennis Reed
>             Fix For: 3.2.9.GA
>
>         Attachments: JTSCache.java
>
>
> 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 at 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.

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.jboss.org/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira