Server hanging with ARJUNA012378: ReaperElement appears to be wedged

[ianmacintyre]

Hi folks,

We are having a strange issue with Transaction Reaper threads becoming wedged, which appears to lock up the entire server.  A restart is then needed, however it only happens on some machines - not all.  This is running Wildfly 10.0.

The initial symptom is a transaction timeout which the reaper attempts to abort.  From the stacktrace we see it is happening in our code - waiting on the db to return (or a call to an external system).  This part I can understand.

Then, within 2s I see a warning the Reaper element is wedged.  The stack trace at that point seems to point to JBoss logging

2017-07-14 08:10:22,602 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012378: ReaperElement appears to be wedged: java.security.AccessController.doPrivileged(Native Method)

org.jboss.logmanager.formatters.Formatters$14.renderRaw(Formatters.java:638)

org.jboss.logmanager.formatters.Formatters$JustifyingFormatStep.render(Formatters.java:225)

org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:83)

org.jboss.logmanager.ExtFormatter.format(ExtFormatter.java:32)

org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:46)

org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76)

org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:314)

org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:322)

org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:322)

org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:322)

org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:322)

org.jboss.logmanager.Logger.logRaw(Logger.java:850)

org.jboss.logmanager.Logger.log(Logger.java:802)

org.jboss.logging.JBossLogManagerLogger.doLog(JBossLogManagerLogger.java:44)

org.jboss.logging.Logger.logv(Logger.java:2256)

com.arjuna.ats.arjuna.logging.arjunaI18NLogger_$logger.warn_coordinator_CheckedAction_2(arjunaI18NLogger_$logger.java:775)

...more

(the above happens perhaps about 90% of the time - however sometimes the stack trace doesnt seem to reflect anything)

2017-07-14 08:08:15,779 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012378: ReaperElement appears to be wedged: com.arjuna.ats.arjuna.coordinator.CheckedAction.check(CheckedAction.java:67)

com.arjuna.ats.arjuna.coordinator.BasicAction.checkChildren(BasicAction.java:3387)

com.arjuna.ats.arjuna.coordinator.BasicAction.Abort(BasicAction.java:1651)

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)

jstack thread dumps are not showing anything obvious, and it is not happening on every machine.  On my local dev box if I knock the transaction timeout down to 30s then simulate long running transactions which timeout I cannot get the same results - the transaction times out and the Reaper aborts it - but there is no subsequent wedged thread (of course I am just running single user where as the other servers are under load).

Anyone seem anything similar and has any pointers to debugging.

Thanks

Ian

[jaikiran]

I'm not too sure what that exception message means or what could potentially contribute to it and how to debug/reproduce it. Maybe the transaction team (tomjenkinson mmusgrov) knows a bit more about it?

[tomjenkinson]

It looks like something with the security manager - zhfeng - please can you take a look?

[zhfeng]

These stack trace look like being printed when the reaper is checking the element which is under the status of CANCEL

https://github.com/jbosstm/narayana/blob/master/ArjunaCore/arjuna/classes/com/arjuna/ats/arjuna/coordinator/TransactionReaper.java#L210

The call to the cancel() can not response within the _cancelWaitPeriod which the default value is 500ms. So it looks like the machine is under the heavy load. Can you set TRACE logger level of com.anjuna and re-run to find more details ?

[ianmacintyre]

Thanks for the responses.  I've put in a request for the additional logging.

[jaikiran]

Minor correction to what Amos asked for in his comment - there's a typo in Amos' comment. The TRACE level logging needs to be configured for com.arjuna and not com.anjuna.

[rickyterzis]

Hi...These stack trace look like being printed when the reaper is checking the element which is under the status of CANCEL

The call to the cancel() can not response within the _cancelWaitPeriod which the default value is 500ms. So it looks like the machine is under the heavy load. Can you set TRACE logger level of com.anjuna and re-run to find more details ?

pcb assembly china

[tomjenkinson]

Arjuna uses async thread to rollback timed out transactions. I wondered if the message was something to do with SecMgr but it looks like it is just a cropped stack trace actually.

What you need to do is work on why the original thread is getting stuck in its business logic. It is possible that the server is stuck because too many threads are stuck at the DB and there are no business logic executors available.

[ianmacintyre]

This is the approach we are taking.  Our business logic definitely "has room for improvement" performance-wise and if we can make that problem go away that will hopefully address the hanging issues.