Transaction Reaper Worker is causing a deadlock

[ali.alwadi]

Hi All,

We have a client Production system which holds the queues to do the back office batch processing. We have a dead-lock situation when apparently one queue threads is locked waiting for Transaction Reaper thread to commit/Rollback the transaction in order to close it off.

The issue is similar to https://developer.jboss.org/thread/219642, except in our case I couldn't find the relevant code in our application.

Please see below the relevant part of the thread dump. Unfortunately, as this is a production environment, I couldn't get a heapdump,

Found one Java-level deadlock:
=============================
"GENQ-2":
  waiting to lock monitor 0x00007f8d6620c718 (object 0x00000006c33457f0, a com.arjuna.ats.internal.jta.transaction.arjunacore.AtomicAction),
  which is held by "Transaction Reaper Worker 0"
"Transaction Reaper Worker 0":
  waiting for ownable synchronizer 0x0000000739b40b88, (a java.util.concurrent.locks.ReentrantLock$FairSync),
  which is held by "GENQ-2"

Java stack information for the threads listed above:
===================================================
"GENQ-2":
  at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1573)
  - waiting to lock <0x00000006c33457f0> (a com.arjuna.ats.internal.jta.transaction.arjunacore.AtomicAction)
  at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:118)
  at com.arjuna.ats.arjuna.AtomicAction.abort(AtomicAction.java:188)
  at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.rollbackAndDisassociate(TransactionImple.java:1247)
  at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.rollback(BaseTransaction.java:134)
  at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.rollback(BaseTransactionManagerDelegate.java:114)
  at org.jboss.tm.usertx.client.ServerVMClientUserTransaction.rollback(ServerVMClientUserTransaction.java:175)
  at org.sqlb.sql.transaction.JEETransaction.rollback(JEETransaction.java:71)
  at org.sqlb.call.delegate.server.CallDelegateBase.run(CallDelegateBase.java:317)
  at org.sqlb.call.delegate.server.CallDelegateBase.runVoid(CallDelegateBase.java:250)
  at org.sqlb.call.delegate.server.CallDelegateBase.call(CallDelegateBase.java:63)
  at sun.reflect.GeneratedMethodAccessor2793.invoke(Unknown Source)
  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
  at java.lang.reflect.Method.invoke(Method.java:606)
  at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53)
  at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:36)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.as.jpa.interceptor.SBInvocationInterceptor.processInvocation(SBInvocationInterceptor.java:47)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.as.ejb3.tx.EjbBMTInterceptor.handleInvocation(EjbBMTInterceptor.java:105)
  at org.jboss.as.ejb3.tx.BMTInterceptor.processInvocation(BMTInterceptor.java:56)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
  at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.as.ejb3.component.pool.PooledInstanceInterceptor.processInvocation(PooledInstanceInterceptor.java:51)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.as.ejb3.component.interceptors.AdditionalSetupInterceptor.processInvocation(AdditionalSetupInterceptor.java:32)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
  at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165)
  at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:173)
  at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288)
  at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61)
  at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72)
  at org.company.call.delegate.server.CallDelegate$$$view4.call(Unknown Source)
  at org.company.call.delegate.client.CallDelegateAUTOWrapper.call(CallDelegateAUTOWrapper.java:54)
  at org.company.call.delegate.client.PreparedCallStub.delegateCall(PreparedCallStub.java:125)
  at company.commons.engine.db.DBQueueItem.execPreparedCall(DBQueueItem.java:200)
  at company.commons.engine.db.DBQueueItem.execCALL(DBQueueItem.java:281)
  at company.commons.engine.db.DBQueueItem.execute(DBQueueItem.java:111)
  at org.sqlb.utils.engine.QueueThread.run(QueueThread.java:163)
"Transaction Reaper Worker 0":
  at sun.misc.Unsafe.park(Native Method)
  - parking to wait for <0x0000000739b40b88> (a java.util.concurrent.locks.ReentrantLock$FairSync)
  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:867)
  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1197)
  at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:229)
  at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290)
  at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.lock(BaseWrapperManagedConnection.java:361)
  at org.jboss.jca.adapters.jdbc.local.LocalManagedConnection.rollback(LocalManagedConnection.java:113)
  at org.jboss.jca.core.tx.jbossts.LocalXAResourceImpl.rollback(LocalXAResourceImpl.java:222)
  at com.arjuna.ats.internal.jta.resources.arjunacore.XAOnePhaseResource.rollback(XAOnePhaseResource.java:187)
  at com.arjuna.ats.internal.arjuna.abstractrecords.LastResourceRecord.topLevelAbort(LastResourceRecord.java:126)
  at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2874)
  at com.arjuna.ats.arjuna.coordinator.BasicAction.doAbort(BasicAction.java:2853)
  at com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1616)
  - locked <0x00000006c33457f0> (a com.arjuna.ats.internal.jta.transaction.arjunacore.AtomicAction)
  at com.arjuna.ats.arjuna.coordinator.TwoPhaseCoordinator.cancel(TwoPhaseCoordinator.java:118)
  at com.arjuna.ats.arjuna.AtomicAction.cancel(AtomicAction.java:217)
  at com.arjuna.ats.arjuna.coordinator.TransactionReaper.doCancellations(TransactionReaper.java:370)
  at com.arjuna.ats.internal.arjuna.coordinator.ReaperWorkerThread.run(ReaperWorkerThread.java:78)

Found 1 deadlock.

More information can be provided on request.

Note that this has been reported in StackOverFlow

Thank you.

[zhfeng]

Hi Ali,

It looks like the application is running in the JBoss AS container. can you provide which version you are used if it is the Wildfly or the JBoss EAP server ?

Thanks,

Amos

[ali.alwadi]

Hi Amos,

Thank you for your quick reply.

Sorry I should have mentioned this. The JBoss version is JBoss 7.1.1-Final, JDK version is 1.7.0_97

[mmusgrov]

This situation is usually caused by the application trying to finish a transaction before it has closed the connection. When the reaper triggers is finds the connection in use so cannot lock it before doing the rollback (the BaseWrapperManagedConnection.lock statement in the reaper stacktrace). Can you ensure that your app closes the connection before trying to finish the transaction.

[tomjenkinson]

As you are probably aware 7.1.1 is very old (2012). We are actually working on version 14 now (GitHub - wildfly/wildfly at 14.0.0.Beta1 ) are you able to update to a more recent version of the application server?

I found this JBTM issue that was closed as cannot reproduce: [JBTM-1951] Deadlock in JBOSS Transaction Reaper - JBoss Issue Tracker  it seems there were issues reported with JCA deadlock:

[JBPAPP-5596] Incorrect handling of multi-threaded access to JCA connections - JBoss Issue Tracker

[JBPAPP-6684] Deadlock in JCA when TM tries to commit/rollback - JBoss Issue Tracker

/cc maeste

Also, I will move this to the WildFly space as it affects the integration rather than just Narayana

[ali.alwadi]

Hi Michael,

Thank you for your response.

I suspected that would be the case when the issue was first reported, but since our application is huge, I tried to check everywhere for any improper closure for DB connections, I couldn't find any. What really bother me is that we haven't been able to reproduce this error locally.

[tomjenkinson]

Let's ask some more people who are familiar with IronJacamar tomekadamski

[ali.alwadi]

Hi Tom,

Thank you for your reply.

I am aware of that, in fact we have scheduled an upgrade to latest JBoss-EAP early next year, but it would be nice if we can replicate and fix this issue before then.

Please feel free to move this as you feel necessary

Thanks

[tomekadamski]

Hi Ali,

I gave a look at the issue but for now, I cannot establish what may be a cause of the problem. I will give it a more thorough look in the following days and will inform you if I manage to find some solution (or have some questions regarding your use case).

Tomek

[ali.alwadi]

Hi Tomasz,

Thank you for picking this up so quickly. I appreciate your help on this.

[tomjenkinson]

We can also mention it to maeste

[tomekadamski]

Hi ali.alwadi,

I was analyzing the code but could not find the parts that can lead to the deadlock. The issue is intermittent and has no reproducer. Furthermore, you are using a very old version of WildFly (JBoss actually ).  As a result, at the moment we wouldn't be able to help.  Please, upgrade your system to the latest version of WildFly. If the deadlock happens to persist, we would have to enable lock tracing and debug step by step what is happening.

[ali.alwadi]

Thank you Tom and Tomasz