Premature transaction timeout.

[whitingjr]

Hi,

Since this hibernate HHH-7689 issue has been fixed I have been able to use an internal benchmark. The benchmark uses jdbc batching to prepare initial data for a benchmark run with a relational database like PostgreSQL.

Depending on the environment I use the loading of data takes different amounts of time. I am seeing a problem on "slow" hardware. ie my local laptop and desktop versus dedicated servers.

What I am seeing is the loading of data fail. Loading the data takes a while so the Recovery Manager rightly detects a timeout and aborts the transaction. Using the default of 300 seconds.

To get round this I've attempted two things. By setting the default-timeout attribute on the coordinator-environment element in the server configuration file.

<coordinator-environment default-timeout="300"/>

a) Set a adequately high timeout (in seconds). e.g. 1200 (an hour)

<coordinator-environment default-timeout="1200"/>

b) disable the timeout. Using -1

<coordinator-environment default-timeout="-1"/>

In both situations I find the Recovery Manager does not do what I am expecting. Which is avoid timing out the long running transaction sufficiently long enough for the data to load.

To demonstrate test case a) is attached a Wildfly 8.1 server log file. With TRACE logging enabled for "com.arjuna.ats.arjuna" category. The data loading was initiated after the server completed the start-up sequence. This demonstrates the recovery manager aborting the transaction at 10:34:10,274 after 694 seconds (11 minutes 34).

I wonder if the tx is being marked abort for other reasons. Is there a different category I can use to show this ?

Regards,

Jeremy

Tested hibernate-core

4.3.1.Final Wildfly 8.1.0.Final

4.2.14.Final in EAP 6.3.0.Beta

Using PostgreSQL 9.2.8.

$ java -version

java version "1.7.0_65"

OpenJDK Runtime Environment (fedora-2.5.1.2.fc19-x86_64 u65-b17)

OpenJDK 64-Bit Server VM (build 24.65-b04, mixed mode)

$ uname -a

Linux burtha02-f19 3.14.13-100.fc19.x86_64 #1 SMP Fri Jul 18 02:36:00 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

[tomjenkinson]

Just to keep the forum in the loop, we discussed this on the chat room and I observed that the transaction timeout was set to 600s and did fire exactly at that point.

To understand whether the default timeout is being incorrectly set to 600 Jeremy is going to bookmark:

narayana/CoordinatorEnvironmentBean.java at 4.17 · jbosstm/narayana · GitHub

https://github.com/jbosstm/narayana/blob/4.17/ArjunaCore/arjuna/classes/com/arjuna/ats/arjuna/common/CoordinatorEnvironmentBean.java#L486

Assuming that does not present the answer, he will look at:

https://github.com/jbosstm/narayana/blob/4.17/ArjunaCore/arjuna/classes/com/arjuna/ats/arjuna/AtomicAction.java#L116

To see if the app is somehow setting the timeout to 600.

Tom

[whitingjr]

Setting the two breakpoints show several stack traces. A file is attached for each.

A quick analysis of each stack trace shows the following.

trace number, setTimeout value, Object

trace number	set timeout value	object	business operation
01	1200	AtomicAction	createDistributionCenters
02	1200	AtomicAction	createDistributionCenters
03	0	AtomicAction	createDistributionCenters
04	0	AtomicAction	createDistributionCenters
05	600	AtomicAction	createCustomers
06	600	AtomicAction	createCustomers
07	600	AtomicAction	createCustomers
08	600	AtomicAction	createCustomers

Taking a look at the business methods in some detail shows.

• createDistributionCenters is not annotated.
• createCustomers method is marked with @TransactionTimeout(600)

This solves where the 600 second timeout comes from. Thus the data load generally. I'll comment out the line in the code to get it working.

How about the createDistributionCenters methods. They switch values after two invocations.

Jeremy

[tomjenkinson]

Hi Jeremy,

I think you need to track through https://github.com/jbosstm/narayana/blob/4.17/ArjunaJTA/jta/classes/com/arjuna/ats/internal/jta/transaction/arjunacore/BaseTransaction.java#L86 follow the timeout value to determine why it is being set to zero.

This would also be a good breakpoint: https://github.com/jbosstm/narayana/blob/4.17/ArjunaJTA/jta/classes/com/arjuna/ats/internal/jta/transaction/arjunacore/BaseTransaction.java#L175

Hope it helps,

Tom

[whitingjr]

Thank you for the suggestion. I did step through what's going on for calls 01 to 04.

The first two invocations seem to be using EJB with RequiresNew transaction demarcation. Before the operation is called the "old" timeout value is being accessed and held in a local variable. To be re-assigned later after the business operation is complete.

The method wildfly/CMTTxInterceptor.java at 8.1.0.Final · wildfly/wildfly · GitHub is called to get the existing value. Which is zero in the first two operations of createDistributionCenters.

After they return the zero is set on this line wildfly/CMTTxInterceptor.java at 8.1.0.Final · wildfly/wildfly · GitHub making calls 03 and 04 start up with zero as the initial timeout value.

That doesn't look right to me. What do you think ?

Jeremy

[tomjenkinson]

I wonder why the following is evaluation to false: https://github.com/wildfly/wildfly/blob/8.1.0.Final/ejb3/src/main/java/org/jboss/as/ejb3/tx/CMTTxInterceptor.java#L131

Please can you find out what the class of the tm reference is in the debugger?

Thanks,

Tom

[whitingjr]

Interestingly the type of the tm variable is TransactionTimeoutConfiguration. Which means the code steps into the if true block wildfly/CMTTxInterceptor.java at 8.1.0.Final · wildfly/wildfly · GitHub. That then calls

https://github.com/jbosstm/narayana/blob/5.0.0.Final/ArjunaJTS/integration/src/main/java/com/arjuna/ats/jbossatx/jta/TransactionManagerDelegate.java#L60

which calls

narayana/BaseTransaction.java at 5.0.0.Final · jbosstm/narayana · GitHub

The return value from BaseTransaction is zero.

Is it possible the _timeouts threadlocal field on BaseTransaction isn't correctly configured ?

Jeremy

[tomjenkinson]

Hi Jeremy,

I think there is a wierd interplay between what the EJB interceptor expects from getTransactionTimeout and what it actually does. It returns the value set for the thread, rather than a default if nothing is set yet, which may explain why sometimes you see 1200 and sometimes you see 0 in your thread dumps. That said, I believe the right thing is eventually happening as if you look here: narayana/AtomicAction.java at master · jbosstm/narayana · GitHub you can see that in the case where zero is passed in, we will modify that to the default value anyway.

So, if you removed all other breakpoints and put one here:

https://github.com/jbosstm/narayana/blob/master/ArjunaCore/arjuna/classes/com/arjuna/ats/arjuna/AtomicAction.java#L131

You would hopefully see that the transaction manager is doing the right thing.

It may be worth keeping the EJB code as it is to allow it to integrate with other transaction managers which work as that code expects given that it doesn't (I think) affect the behaviour of Narayana.

Tom

[whitingjr]

Hi Tom,

Yes you are right and the breakpoint you suggested did prove useful for my testing to check the transaction manager is doing the right thing.

That line does show the recovery manager is set to use the correct timeout value. By checking if the value is 0 then getting the default timeout from TxControl.

Many thanks in helping me check things over.

Regards,

Jeremy