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

Dennis Reed (JIRA) jira-events at lists.jboss.org
Fri Jun 1 13:19:17 EDT 2012


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

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

           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 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.


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


    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 (could not reproduce with LOCAL, possibly just because of timing).

Start two nodes in a cluster.

In multiple threads, run the following in a loop:

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

(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."

  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 (could not reproduce with LOCAL, possibly just because of timing).

Start two nodes in a cluster.

In multiple threads, run the following in a loop:

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

(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
>
> 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

        


More information about the jbosscache-issues mailing list