JBossTS Tx timeout (with CMT beans)

[dimitris]

I was seeing random failures with org.jboss.test.tm.test.TxTimeoutUnitTestCase - testOverriddenTimeoutExpires()

The timeout is set to 5'' while the bean is actually waiting 8'' inside a method. Some times the asynchronous timeout/rollback doesn't happen and I had to do a 7'' [+ 2''] seconds sleep to make it reliably pass (at least locally).

I'm wondering how tx timeouts are implemented by JBoss TS. Is there a thread that wakes up periodically (e.g. every 5'') and evaluates the timeouts or does it wake up at the exact timeout time?

Does it deal with the timeouts themselves in separate threads?

[jhalliday]

> Is there a thread that wakes up periodically (e.g. every 5'') and evaluates the timeouts or does it wake up at the exact timeout time?

Either way depending on configuration, although 'exact' is still a bit flexible.

> Does it deal with the timeouts themselves in separate threads?

yes.

[dimitris]

I guess, I can look it up myself but what's the default for AS ?

[jhalliday]

Periodic:

Transaction Reaper Mode, can be: NORMAL or DYNAMIC (default is NORMAL).

[jhalliday]

BTW I'm pretty sure the docs are wrong - The timeout value is in ms, not microsecs. Try setting the mode to DYNAMIC or keep NORMAL but shorten the txReaperTimeout from 120000 to 2000 or so.

[dimitris]

Unless there is a strong reason not to, we should really change Tx Reaper Mode to DYNAMIC, that was how the old TM behaved and how applications are coded.

Also fix the comment about microsecs. (this setting is ignored when in DYNAMIC mode, right?)

Do you want to make those changes in svn ? We need a JIRA to track it in JBAS.

https://svn.jboss.org/repos/repository.jboss.org/jboss/jbossts14/4.2.3.SP5/resources/jbossjta-properties.xml

[dimitris]

Also with the default setting (NORMAL/120000) it's quite strange that tests work, even sometimes, if the reaper thread is only kicking in every 2 minutes??? I'll see if I can enable logging to see it running.

[marklittle]

You need to remember that these are not hard real-time deadlines. All the specification says is that if the transaction hasn't rolled back by the time the time-out goes off, it'll be rolled back automatically. But it doesn't say that a transaction will be rolled back immediately. There are trade-offs to be made: immediacy can imply more overhead, whereas "sometime afterwards" may mean you don't see the timeout happen for a while, but there's less overhead. That's why we support a couple of modes, to give flexibility.

[marklittle]

"jhalliday" wrote:
BTW I'm pretty sure the docs are wrong - The timeout value is in ms, not microsecs. Try setting the mode to DYNAMIC or keep NORMAL but shorten the txReaperTimeout from 120000 to 2000 or so.

There's definitely an inconsistency in the docs:

"The default checking period is 120000 milliseconds, but can be overridden by
setting the com.arjuna.ats.arjuna.coordinator.txReaperTimeout property
variable to another valid value, in microseconds."

The reference to microseconds should be milliseconds.

http://jira.jboss.com/jira/browse/JBTM-236

[marklittle]

Unless there is a strong reason not to, we should really change Tx Reaper Mode to DYNAMIC, that was how the old TM behaved and how applications are coded.

All the old TM did was mark the transactions for rollback at that time, i.e., place them into a state from which they could only ever roll back. It didn't roll them back then though. That came later (potentially never), when the creating thread terminated the transaction.

[dimitris]

I think the executing thread was also interrupted. So if was stuck on I/O the rollback would be performed immediately after that.

[marklittle]

You could be right, I haven't checked that. But I do know the majority of support cases we've had around the old TM and timeouts were due to it not rolling back. So the expectation is definitely that we should roll back asap (no good definition of asap ;-), but the old TM behaviour didn't match that.

[dimitris]

I've managed (finally) to enable logging (that would be another topic of discussion apparently).

With the default settings:

comm.arjuna.ats.arjuna.coordinator.txReaperTimeout=120000
com.arjuna.ats.arjuna.coordinator.txReaperMode=NORMAL

I'm just seeing a Repear thread working every 5 seconds, so I don't know what this txReaperTimeout actually does. Maybe it is microsecs by it defaults to 5 secs minimum???

sleeping for 5000
2007-06-19 22:24:33,542 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::check ()
2007-06-19 22:24:33,542 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.internal.arjuna.coordinator.ReaperThread_1] - Thread Thread[Thread-4,5,jboss]
sleeping for 5000
2007-06-19 22:24:38,549 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::check ()
2007-06-19 22:24:38,549 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.internal.arjuna.coordinator.ReaperThread_1] - Thread Thread[Thread-4,5,jboss]
sleeping for 5000
2007-06-19 22:24:43,556 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::check ()

[marklittle]

Definitely shouldn't be running more frequently than the timeout defines. Will take a look.

[marklittle]

BTW, while I check, do you see anything in your debug output like:

[com.arjuna.ats.internal.arjuna.coordinator.ReaperThread_1] - Thread FOO sleeping for BAR