JBoss Community

Transaction Timeouts and EJB3/JPA

Posted on 2008-11-23 01:16:00.0 by John Mazz [ View original post ]

I recently discovered somewhat odd behavior in the way transactions are timed out in my EJB3/JPA app. It was surprising to me how it worked, and though I guess it makes sense when thinking about it, something here still doesn't "feel right".

Consider an EJB3/JPA application deployed in JBossAS 4.2 that uses the Arjuna's Transaction Manager (aka JBossTM - although I still call it Arjuna :) and Hibernate as the JPA implementation.

Annotating an EJB3 stateless session bean (SLSB) method, is this:

@org.jboss.annotation.ejb.TransactionTimeout(60)

If my method takes longer than 60 seconds, the transaction it is running in will timeout, and thus rollback. But, what happens if my method is executing a very long running SQL update? Or, maybe my method is simply writing out a very long data file to a remote file system. Or, maybe I'm just stupid and my method is executing "Thread.sleep(30 * 60 * 1000)"? In other words, what happens if my method takes longer than this transaction timeout?

What I was assuming would happen is the thread running my method would get interrupted, and (assuming the JDBC driver or file IO subsystem or Thread.sleep or whatever my method was doing at the time can handle the interrupt) the method would abort with that interrupted exception and immediately begin the rollback procedures. It would do this because once the method exits, the EJB3 interceptor chain would begin to unroll and eventually hit the transaction manager interceptors whose job it is to abort the transaction.

That is close to what happens, but not exactly.

It turns out, the transaction manager detects that the transaction has timed out and aborts it from within an asynchronous thread (different from the thread running my method), but it never sends an interrupt to my method. So, my method continues on even after the timeout period and only when it returns will that interceptor chain finally get a chance to abort the transaction. But by this time, its already been aborted! The interceptor kindly tells me this in a log message, but it's late to the party - the transaction has already been rolled back. This doesn't actually cause any harm because the transaction manager simply says, "this has already been aborted and the rollback was performed earlier, I'll just log a warning and skip the abort procedure".

But, I question why my method was not given a chance to abort also. It is possible that my method could run for 60 minutes, do everything completely successfully, yet, because it exceeded the transaction timeout the entire transaction was rolled back and that 60 minutes worth of work now becomes wasted.

Of course, the answer to that would be, "just set your transaction timeout to a higher value". But that's not really my point. My point is, why is my thread even allowed to waste its time when the transaction manager knows the timeout has expired and the transaction has been rolled back? I think it should at least attempt to warn the thread about the situation by sending an interrupt to it (at that point, it would be my method's job to handle the thrown InterruptedException).

I've tested this to see if an interrupt is sent and I don't see it. See below for the log messages I see after running some test code. I had an SLSB method annotated with a transaction timeout of 2 seconds, and in my SLSB method, I block within a "Thread.sleep(10000)" call (so it pauses in my method for 10 seconds). Take note of the log timestamps and notice that my sleep is allowed to return normally after 10 seconds, but after the 2nd second, you see the transaction manager aborted my transaction! Therefore, my method was allowed to continue until it returned normally - at which time, the interceptor chain tried to abort the transaction a second time:

2008-11-23 01:09:33 INFO  [STDOUT] !!!!!!!!!BEFORE SLEEP
2008-11-23 01:09:35 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N]
[com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action
id a0b0c21:ab6:4928f32d:1225 invoked while multiple threads active within it.
2008-11-23 01:09:35 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N]
[com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check
- atomic action a0b0c21:ab6:4928f32d:1225 aborting with 1 threads active!
2008-11-23 01:09:43 INFO  [STDOUT] !!!!!!!!!AFTER SLEEP
2008-11-23 01:09:43 WARN  [com.arjuna.ats.arjuna.logging.arjLoggerI18N]
[com.arjuna.ats.arjuna.coordinator.BasicAction_40] - Abort called on
already aborted atomic action a0b0c21:ab6:4928f32d:1225
2008-11-23 01:09:43 ERROR [test.slsb] Failed. Cause:
java.lang.IllegalStateException: [com.arjuna.ats.internal.jta.transaction.arjunacore.inactive]
[com.arjuna.ats.internal.jta.transaction.arjunacore.inactive] The transaction is not active!
java.lang.IllegalStateException: [com.arjuna.ats.internal.jta.transaction.arjunacore.inactive]
[com.arjuna.ats.internal.jta.transaction.arjunacore.inactive] The transaction is not active!
at com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple.commitAndDisassociate(TransactionImple.java:1372)
at com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction.commit(BaseTransaction.java:135)
at com.arjuna.ats.jbossatx.BaseTransactionManagerDelegate.commit(BaseTransactionManagerDelegate.java:87)
at org.jboss.aspects.tx.TxPolicy.endTransaction(TxPolicy.java:175)
at org.jboss.aspects.tx.TxPolicy.invokeInOurTx(TxPolicy.java:87)
at org.jboss.aspects.tx.TxInterceptor$RequiresNew.invoke(TxInterceptor.java:262)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.tx.TxPropagationInterceptor.invoke(TxPropagationInterceptor.java:76)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:62)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.aspects.security.AuthenticationInterceptor.invoke(AuthenticationInterceptor.java:77)
at org.jboss.ejb3.security.Ejb3AuthenticationInterceptor.invoke(Ejb3AuthenticationInterceptor.java:106)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.ENCPropagationInterceptor.invoke(ENCPropagationInterceptor.java:46)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.asynchronous.AsynchronousInterceptor.invoke(AsynchronousInterceptor.java:106)
at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:101)
at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:214)
at org.jboss.ejb3.stateless.StatelessContainer.localInvoke(StatelessContainer.java:184)
at org.jboss.ejb3.stateless.StatelessLocalProxy.invoke(StatelessLocalProxy.java:81)
     ...

It is also interesting to note that the transaction manager knows that a thread is still running my method - see its log message: "aborting with 1 threads active".

This is worrisome to me because I could run into a condition where my SLSB methods might waste a whole lot of time processing a query or doing other work well after my timeout has triggered the rollback (unless I set my timeouts to some really high value that I know will never expire but then, what's the point of the timeout?). I would rather have my method be interrupted so I don't waste the system resources doing work that is just going to be (or has already been) rolled back. But, for now, without any other options that I know of, I am just going to have to make sure I set my timeouts to some very large values for those methods that may (but most times may not) take a really long time to complete.

I wonder if there is some configuration property I can set on the transaction manager to tell it, "interrupt any active thread that may be running within a transaction that has timed out". I don't know of any such thing, but it just seems like this would be an obvious thing to want to do, so I would not be surprised at all if it turns out that I am just missing a piece of the puzzle. Feel free to comment on this blog if you know of a way to work around this issue or to let me know if there is something I am misunderstanding with respect to the way the transaction manager works (or can be configured to work).

As a side note, I was hoping I could prevent doing the extra, wasted work in the database by circumventing the JPA entity manager and using JDBC statements directly, thereby having access to the java.sql.Statement.setQueryTimeout API but, alas, the Postgres driver does not yet implement that.

---