7 Replies Latest reply on Jul 22, 2016 12:35 PM by mmusgrov

Deadlock seen with Narayana 5.0.4 and WildFly 8.2.1.Final

bvnghiem1012 Jul 17, 2016 10:42 PM

Hi all,

I do upgrade Narayana 5.0.0 on WildFly 8.2.1. Final to 5.0.4 to fix some issues. Now I am seeing a deadlock as below. The reaper thread is creating a deadlock against a DB reading thread.

Found one Java-level deadlock:

=============================

"Transaction Reaper Worker 21":

waiting for ownable synchronizer 0x0000000521acc560, (a java.util.concurrent.locks.ReentrantLock$FairSync),

which is held by "default task-393"

"default task-393":

waiting to lock monitor 0x00007f024c73bce8 (object 0x000000059efbaf30, a com.arjuna.ats.internal.jta.transaction.arjunacore.AtomicAction),

which is held by "Transaction Reaper Worker 21"

Java stack information for the threads listed above:

===================================================

"Transaction Reaper Worker 21":

at sun.misc.Unsafe.park(Native Method)

- parking to wait for <0x0000000521acc560> (a java.util.concurrent.locks.ReentrantLock$FairSync)

at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)

at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)

at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)

at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)

at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)

at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)

at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.lock(BaseWrapperManagedConnection.java:373)

at org.jboss.jca.adapters.jdbc.local.LocalManagedConnection.rollback(LocalManagedConnection.java:113)

at org.jboss.jca.core.tx.jbossts.LocalXAResourceImpl.rollback(LocalXAResourceImpl.java:242)

at com.arjuna.ats.internal.jta.resources.arjunacore.XAOnePhaseResource.rollback(XAOnePhaseResource.java:205)

at com.arjuna.ats.internal.arjuna.abstractrecords.LastResourceRecord.topLevelAbort(LastResourceRecord.java:126)

at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2993)

at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2972)

at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1675)

- locked <0x000000059efbaf30> (a com.arjuna.ats.internal.jta.transaction.arjunacore.AtomicAction)

at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:127)

at com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)

at com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:381)

at com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)

"default task-393":

at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1632)

- waiting to lock <0x000000059efbaf30> (a com.arjuna.ats.internal.jta.transaction.arjunacore.AtomicAction)

at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:127)

at com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:186)

at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1189)

at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:126)

at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)

at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.commit(ServerVMClientUserTransaction.java:173)

at org.springframework.transaction.jta.JtaTransactionManager.doCommit(JtaTransactionManager.java:1010)

at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:754)

at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:723)

at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:393)

at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:120)

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)

at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)

at com.sun.proxy.$Proxy175.findUserByName(Unknown Source)

Any hint about this issue is appreciated.

Thanks,

Nghiem

1. Re: Deadlock seen with Narayana 5.0.4 and WildFly 8.2.1.Final

bvnghiem1012 Jul 17, 2016 11:10 PM (in response to bvnghiem1012)

Following Logs are seen:
2016-07-13 18:36:07,197 WARN [Transaction Reaper]-[com.arjuna.ats.arjuna] ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff64010127:1440db3b:5785f840:2af2e588 in state RUN
2016-07-13 18:36:07,211 WARN [Transaction Reaper Worker 22]-[com.arjuna.ats.arjuna] ARJUNA012095: Abort of action id 0:ffff64010127:1440db3b:5785f840:2af2e588 invoked while multiple threads active within it.
2016-07-13 18:36:07,211 WARN [Transaction Reaper Worker 22]-[com.arjuna.ats.arjuna] ARJUNA012108: CheckedAction::check - atomic action 0:ffff64010127:1440db3b:5785f840:2af2e588 aborting with 1 threads active!
2016-07-13 18:36:07,824 WARN [Transaction Reaper]-[com.arjuna.ats.arjuna] ARJUNA012117: TransactionReaper::check timeout for TX 0:ffff64010127:1440db3b:5785f840:2af2e588 in state CANCEL
2016-07-13 18:36:07,873 WARN [Transaction Reaper]-[com.arjuna.ats.arjuna] ARJUNA012378: ReaperElement appears to be wedged: sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)
java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.lock(BaseWrapperManagedConnection.java:373)
org.jboss.jca.adapters.jdbc.local.LocalManagedConnection.rollback(LocalManagedConnection.java:113)
org.jboss.jca.core.tx.jbossts.LocalXAResourceImpl.rollback(LocalXAResourceImpl.java:242)
com.arjuna.ats.internal.jta.resources.arjunacore.XAOnePhaseResource.rollback(XAOnePhaseResource.java:205)
com.arjuna.ats.internal.arjuna.abstractrecords.LastResourceRecord.topLevelAbort(LastResourceRecord.java:126)
com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2993)
com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2972)
com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1675)
com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:127)
com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:215)
com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:381)
com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)
Actions
2. Re: Deadlock seen with Narayana 5.0.4 and WildFly 8.2.1.Final

mmusgrov Jul 18, 2016 6:37 AM (in response to bvnghiem1012)

The reaper thread is waiting for lock 0x0000000521acc560 which will be a lock on the connection to the database. But this lock is held by the application thread (default task-393). My understanding is that closing the connection will release the lock: are you closing it before attempting to commit the transaction?
Actions
3. Re: Deadlock seen with Narayana 5.0.4 and WildFly 8.2.1.Final

bvnghiem1012 Jul 19, 2016 4:43 AM (in response to mmusgrov)

Hi Micheal,

Thank for your reply!

The connection is pooled connection (within my datasource). So it should not be closed. My doubt is: why the reaper thread do clean up while the transaction is in commit phase (my application thread)? The transaction is committing and it should not be cleaned up by transaction reaper right?
Actions
4. Re: Deadlock seen with Narayana 5.0.4 and WildFly 8.2.1.Final

mmusgrov Jul 21, 2016 3:51 AM (in response to bvnghiem1012)

The transaction timed out and we are cancelling it (via the reaper). At the same time the application thread is attempting the commit. We handle this case by making sure the cancel/abort methods are synchronized. However, we do not expect the application to be using the connection at the time of the commit (the findUserByName() call at the bottom of the stacktrace). The app thread is doing the commit via some AOP logic. Will you check your AOP pointcuts and verify that they do not try to commit the transaction whilst the app is performing actions on the database connection?
Actions
5. Re: Deadlock seen with Narayana 5.0.4 and WildFly 8.2.1.Final

tomjenkinson Jul 22, 2016 9:13 AM (in response to bvnghiem1012)

The reaper operates asynchronously to release locks held in resource managers.

You need to close the connection before the commit from my recollection as when else would you be able to call close? There are some notes here I found from grepping: java - Closing JDBC Connections in Pool - Stack Overflow https://help.sap.com/saphelp_nw74/helpdata/en/49/2add085d561907e10000000a42189c/content.htm

The Connection::close will not close the physical connection, the container should do the right thing.

/cc maeste
Actions
6. Re: Deadlock seen with Narayana 5.0.4 and WildFly 8.2.1.Final

bvnghiem1012 Jul 22, 2016 10:50 AM (in response to tomjenkinson)

Thank Tom, Micheal,

This deadlock happened when my DB server was gone.
I think the transaction was timed out as Micheal's suspection.
Just a bit confusing when I can see the call commitTransactionAfterReturning() of Spring. So I though that the cal findUserByName() was successful.

In this application. I use Spring, Hibernate and JTA.

I think the issue come from DB server connection problem.
Thanks again. Your answers are appreciated.
Nghiem
Actions
7. Re: Deadlock seen with Narayana 5.0.4 and WildFly 8.2.1.Final

mmusgrov Jul 22, 2016 12:35 PM (in response to bvnghiem1012)

Your application thread is still using the connection when your AOP pointcut (or is the terminology advice) code tries to commit the transaction. You should not be using the connection at the same time that you call commit. You need to check the way the app is written and configured and identify where you are still holding onto and using the connection when the AOP advice triggers. I would start with findUserByName and then investigate from there, for example check that you are not ignoring execeptions etc.
Actions

Go to original post