Friday, February 8, 2013

"Nested Transactions" and Timeouts

While coding up some EJB3 SLSB methods, the following question came up:

If a thread is already associated with a transaction, and that thread calls another EJB3 SLSB method annotated with "REQUIRES_NEW", the thread gets a new (or "pseudo-nested" or for ease-of-writing what I'm simply call the "nested" transaction, even though it is not really "nested" in the true sense of the term) transaction but what happens to the parent transaction while the "nested" transaction is active? Does the parent transaction's timeout keep counting down or is it suspended and will start back up counting down only when the "nested" transaction completes?

For example, suppose I enter a transaction context by calling method A and this method has a transaction timeout of 1 minute. Method A then immediatlely calls a REQUIRES_NEW method B, which itself has a 5 minute timeout. Now suppose method B takes 3 minutes to complete. That is within B's allotted 5 minute timeout so it returns normally to A. A then immediately returns.

But A's timeout is 1 minute! B took 3 minutes on its own. Even though the amount of time A took within itself was well below its allotted 1 minute timeout, its call to B took 3 minutes.

What happens? Does A's timer "suspend" while its "nested" transaction (created from B) is still active?  Or does A's timer keep counting down, regardless of whether or not B's "nested" transaction is being counted down at the same time (and hence A will abort with a timeout)?

Here's some code to illustrate the use-case (this is what I actually used to test this):

@TransactionAttribute(TransactionAttributeType.REQUIRES_NEW)
@TransactionTimeout(value = 5, unit = TimeUnit.SECONDS)
public void testNewTransaction() throws InterruptedException {
   log.warn("~~~~~ Starting new transaction with 5s timeout...");
   LookupUtil.getTest().testNewTransaction2();
   log.warn("~~~~~ Finishing new transaction with 5s timeout...");
}
@TransactionAttribute(TransactionAttributeType.REQUIRES_NEW)
@TransactionTimeout(value = 10, unit = TimeUnit.SECONDS)
public void testNewTransaction2() throws InterruptedException {
   log.warn("~~~~~ Starting new transaction with 10s timeout...sleeping for 8s");
   Thread.sleep(8000);
   log.warn("~~~~~ Finishing new transaction with 10s timeout...");
}
I don't know what any of the EE specs say about this, but it doesn't matter - all I need to know is how JBossAS7 behaves :) So I ran this test on JBossAS 7.1.1.Final and here's what the log messages say:
17:51:22,935 ~~~~~ Starting new transaction with 5s timeout...
17:51:22,947 ~~~~~ Starting new transaction with 10s timeout...sleeping for 8s
17:51:27,932 WARN  ARJUNA012117: TransactionReaper::check timeout for TX 0:ffffc0a80102:-751071d8:5115811c:449 in state  RUN
17:51:27,936 WARN  ARJUNA012121: TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,main] successfully canceled TX 0:ffffc0a80102:-751071d8:5115811c:449
17:51:30,948 ~~~~~ Finishing new transaction with 10s timeout...
17:51:30,949 ~~~~~ Finishing new transaction with 5s timeout...
17:51:30,950 WARN  ARJUNA012077: Abort called on already aborted atomic action 0:ffffc0a80102:-751071d8:5115811c:449
17:51:30,951 ERROR JBAS014134: EJB Invocation failed on component TestBean for method public abstract void org.rhq.enterprise.server.test.TestLocal.testNewTransaction() throws java.lang.InterruptedException: javax.ejb.EJBTransactionRolledbackException: Transaction rolled back
...
Caused by: javax.transaction.RollbackException: ARJUNA016063: The transaction is not active!
   at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1155) [jbossjts-4.16.2.Final.jar:]
   at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:117) [jbossjts-4.16.2.Final.jar:]
   at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:75)
   at org.jboss.as.ejb3.tx.CMTTxInterceptor.endTransaction(CMTTxInterceptor.java:92) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final]
So it is clear that, at least for JBossAS7's transaction manager, the parent transaction's timer is not suspended, even if a "nested" transaction is activated. You see I enter the first method (which activates my first transaction) at 17:51:22, and immediately enter the second method (which activates my second, "nested", transaction at the same time of 17:51:22). My first transaction has a timeout of 5 seconds, my second "nested" transaction has a timeout of 10 seconds. My second method sleeps for 8 seconds, so it should finish at 17:51:30 (and it does if you look at the log messages at that time). BUT! Prior to that, my first transaction is aborted by the transaction manager at 17:51:27 - exactly 5 seconds after my first transaction was started. So, clearly my first transaction's timer was not suspended and was continually counting down even as my "nested" transaction was active.

So, in short, the answer is (for JBossAS7 at least) - a transaction timeout is always counting down and starts as soon as the transaction activates. It never pauses nor suspends due to "nested" transactions.