Thread associated with transaction suspended for a long time in JBoss 6.1.0

[sridharthiyagarajan]

I am facing a big concern in JBoss 6.1.0. It is a multi threaded application and am using stateless EJB with BMT and Sybase DB. JDK used is 1.7.76u. User transaction is started. Queries got ran but the associated thread tries to commit after ONE HOUR. I am not aware what happened to the thread executing. It is suspended for sure but not from the code.

Can anyone please give a valuable pointer about why the thread got suspended for more than hour. Obviously after an hour, thread resuming and trying either COMMIT or ROLLBACK will fail and has failed as the default transaction timeout is 300 seconds (which is JBoss 6 default value).

2017-01-09 10:01:49,389 DEBUG [TestDAO] [EventId: ] [pool-63-thread-6] SQL SELECT QUERY

2017-01-09 10:01:49,391 DEBUG [TestDAO] [EventId: ] [pool-63-thread-6] ['dao.rowsProcessed']: 1 rows processed

2017-01-09 10:01:49,389 DEBUG [TestDAO] [EventId: ] [pool-63-thread-6] SQL UPDATE QUERY

2017-01-09 10:01:49,391 DEBUG [TestDAO] [EventId: ] [pool-63-thread-6] ['dao.rowsUpdated']: 1 row updated

2017-01-09 11:05:48,213 DEBUG [DAOUtils] [EventId: ] [pool-63-thread-6] commitTx

2017-01-09 11:05:48,214 ERROR [DAOUtils] [EventId: ] [pool-63-thread-6] commitTx() failedARJUNA-16063 The transaction is not active!

2017-01-09 11:05:48,215 DEBUG [DAOUtils] [EventId: ] [pool-63-thread-6] rollbackTx

2017-01-09 11:05:48,215 ERROR [DAOUtils] [EventId: ] [pool-63-thread-6] rollbackTx() java.lang.IllegalStateException - BaseTransaction.rollback - ARJUNA-16074 no transaction!

[andey]

Hi,

It seems you have long running transactions which is being time-out.

"The transaction is not active!" are caused by a transaction timeout.  When a transaction times out the transaction manager rolls it back asynchronously and then when a compontent tries to access the transaction again (e.g. to commit it or roll it back) it won't be able to according to the JTA spec.

The default transaction timeout has been defined under "default-timeout" attribute at "transactions" subsystem in the application server configuration.

- The default is 300 seconds / 5 minutes

- You may modify the value to increase the default transaction timeout

- You may set the value to 0 to disable the transaction reaper / transaction timeout

- The application server VM must be restarted for the default-timeout change to be applied

~~~

<subsystem xmlns="urn:jboss:domain:transactions:1.4">

    ...(snip)...

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

</subsystem>

~~~

It looks to me like your it is taking longer than 5 minutes to process the message therefore its transaction is timing out.

I would recommend you to increase the transaction timeout to a higher figure to avoid this situation. It would be good if you could refactor the application code to reduce the time taken to complete a transaction. So it may be that the application logic is correctly handling the scenario in this case

[sridharthiyagarajan]

Many thanks for the response.. Anup. Varying Timeout parameter may help if the application is always timing out running transactions. The concern I mentioned happens very very sporadically and particularly on a single thread and once this happens, it brings down AS itself. Also, this thread is from any workflow in an application. This is a BIG concern bothering.

In the below piece of code shared, transaction is begun, queries are executed and time taken between them is 139 ms. Now, between closing the preparedStatement, resultSet AND committing the transaction have taken MORE THAN AN HOUR. Here, queries involved are simple (as it involves a very few rows) and the thread which initiated the transaction is suspended for more than hour as ideally it should not be that way as clearly mentioned in the code - the next line of code after closing the resources is committing the transaction.

I believe root cause should revolve around Transaction object, connection object and the associated thread. Hope you understand the problem very clear and if not, please let me know and I will make it even clear. Also, I will be happy if you share in case this is something associated with any open "run time" issues of JBoss-6.1.0.

TestEJB.java:

public TO getList(TO input) {

...

UserTransaction ut = DAOUtils.begin(sessionContext);

TestDAO.getList(input);

DAOUtils.commitTx(ut);

...

}

TestDAO:

public TO getList(TO input) {

     try {

     ...

     ResultSet resultSet = null;  

     PreparedStatement statement = connection.prepareStatement("SQL statement");

     resultSet = select.executeQuery();

     ...

     log.debug("dao.rowsProcessed", resultSet.getCount());   - I could see this log statement in the log file with the date time 2017-01-09 10:01:49,391.

     }

     catch (SQLException e) {

          ...

     } catch (Exception e) {

         ...

     }          

     finally {

     select.close();

     resultSet.close();

     }

}

DAOUtils.java

public UserTransaction begin(SessionContext ctx) {

log.debug("beginTx"); - I could see this log statement in the log file with the date time  2017-01-09 10:01:49,252.

return ctx.getUserTransaction()

}

public void commit(UserTransaction ut) {

log.debug("commitTx"); - I could see this log statement in the log file with the date time 2017-01-09 11:05:48,213 (MORE THAN AN HOUR DIFFERENCE).

ut.commit();

}

[andey]

Hi,

>>>between closing the preparedStatement, resultSet AND committing the transaction have taken MORE THAN AN HOUR

I wonder. it should not be the right behaviour.

Jboss works in any environment that uses JTA, in fact,we recommend to use JTA whenever possible as it is the standard Java transaction interface. You get JTA built-in with all J2EE/JEE application servers, and each Datasource you use in such a container is automatically handled by a JTA TransactionManager.

If you manage your session yourself, code is more difficult to layer. You can't easily move data access operations into a different layer than transaction and Session demarcation.

If you don't have JTA and don't want to deploy it along with your application, you will usually have to fall back to JDBC transaction demarcation. Instead of coding the begin, commit, and rollback of your transactions into your application you could use a declarative approach. For example, you might declare that some of your service or command methods require a database transaction to be started when they are called. The transaction ends when the method returns; if an exception is thrown, the transaction will be rolled back.

Declarative transaction demarcation is a standard feature of EJB, also known as container-managed transactions (CMT).

You can set <idle-timeout-minutes> in your datasource configuration. default is 30 min. You can set as per your application behaviour.

JTA Transaction example:

~~~

public class JDBCExample {

    public static void main (String[] args) {

        Context ctx = new InitialContext();

        // Change these two lines to suit your environment.

        DataSource ds = (DataSource)ctx.lookup("jdbc/ExampleDS");

        Connection conn = ds.getConnection("testuser", "testpwd");

        Statement stmt = null; // Non-transactional statement

        Statement stmtx = null; // Transactional statement

        Properties dbProperties = new Properties();

        // Get a UserTransaction

        UserTransaction txn = new InitialContext().lookup("java:comp/UserTransaction");

        try {

            stmt = conn.createStatement();  // non-tx statement

            // Check the database connection.

            try {

                stmt.executeUpdate("DROP TABLE test_table");

                stmt.executeUpdate("DROP TABLE test_table2");

            }

            catch (Exception e) {

                // assume not in database.

            }

            try {

                stmt.executeUpdate("CREATE TABLE test_table (a INTEGER,b INTEGER)");

                stmt.executeUpdate("CREATE TABLE test_table2 (a INTEGER,b INTEGER)");

            }

            catch (Exception e) {

            }

            try {

                System.out.println("Starting top-level transaction.");

                txn.begin();

                stmtx = conn.createStatement(); // will be a tx-statement

                // First, we try to roll back changes

                System.out.println("\nAdding entries to table 1.");

                stmtx.executeUpdate("INSERT INTO test_table (a, b) VALUES (1,2)");

                ResultSet res1 = null;

                System.out.println("\nInspecting table 1.");

                res1 = stmtx.executeQuery("SELECT * FROM test_table");

                while (res1.next()) {

                    System.out.println("Column 1: "+res1.getInt(1));

                    System.out.println("Column 2: "+res1.getInt(2));

                }

                System.out.println("\nAdding entries to table 2.");

                stmtx.executeUpdate("INSERT INTO test_table2 (a, b) VALUES (3,4)");

                res1 = stmtx.executeQuery("SELECT * FROM test_table2");

                System.out.println("\nInspecting table 2.");

                while (res1.next()) {

                    System.out.println("Column 1: "+res1.getInt(1));

                    System.out.println("Column 2: "+res1.getInt(2));

                }

                System.out.print("\nNow attempting to rollback changes.");

                txn.rollback();

                // Next, we try to commit changes

                txn.begin();

                stmtx = conn.createStatement();

                ResultSet res2 = null;

                System.out.println("\nNow checking state of table 1.");

                res2 = stmtx.executeQuery("SELECT * FROM test_table");

                while (res2.next()) {

                    System.out.println("Column 1: "+res2.getInt(1));

                    System.out.println("Column 2: "+res2.getInt(2));

                }

                System.out.println("\nNow checking state of table 2.");

                stmtx = conn.createStatement();

                res2 = stmtx.executeQuery("SELECT * FROM test_table2");

                while (res2.next()) {

                    System.out.println("Column 1: "+res2.getInt(1));

                    System.out.println("Column 2: "+res2.getInt(2));

                }

                txn.commit();

            }

            catch (Exception ex) {

                ex.printStackTrace();

                System.exit(0);

            }

        }

        catch (Exception sysEx) {

            sysEx.printStackTrace();

            System.exit(0);

        }

    }   

}

see the below link to change your code accordingly:

12.7. Use JTA Transactions

- Application code must handle exceptions that arise while a connection is held (InUse) by the application component

- Upon completion of connection usage (even if the connection has failed), the application code must explicitly call Connection.close() to return the connection to the pool.

- You will want to make sure that your code never caches connections across calls. Connections should be requested, used and closed immediately (calling close() returns them to the pool so that they can be managed by JBoss). Holding connections for long periods of time prevents JBoss from managing them and increases the chance that they will become stale and fail when subsequently used.

[sridharthiyagarajan]

Many thanks for the response.. Anup. Like I mentioned, BMT is used the application and the guide lines you had mentioned are already in place.

There are two possibilities here.

1. Currently resuming thread suspended by JBoss.

2. Memory leak w.r.t. prepared statement.

3. Connection obtained from connection pool is improper.

As I have gone through the code, memory leak w.r.t prepared statement is not possible.

Other two options are:

Currently running thread being suspended by JBoss. As mentioned after an hour, closing prepared statement and result set will pass or fail but not take an hour time. If the currently running thread moves on, then it will either be a success or a failure and in all cases, closing of resources is handled properly.

Is there any possibility that connection obtained from the connection pool can be improper ?

If you could assist if this is some known sporadic concern in JBoss AS 6.1.0 w.r.t. BMT, then it will be very helpful to move forward.

Also, while exploring in the internet, just came across the below error and would like to know what it means. Does it mean result set is closed from the code but not getting closed really by JBoss ?

WARN  [org.jboss.resource.adapter.jdbc.WrappedConnection] (pool-69-thread-13) Error closing a result set you left open! Please close it yourself.: java.sql.SQLException: JZ006: Caught IOException: java.io.IOException: JZ0T3: Read operation timed out.

[andey]

This could certainly be what is leading to the connection pooling issues. As the log states, you are leaving a result set open. This would cause the connection to not be properly closed, which prevents it from being returned to the pool until JBoss comes around and closes it for you.

All applications are responsible for closing all of their resources.

If you ensure that the application is closing all of it's resources, this particular issue should be resolved.

[sridharthiyagarajan]

So, "WARN  [org.jboss.resource.adapter.jdbc.WrappedConnection] (pool-69-thread-13) Error closing a result set you left open! Please close it yourself.: java.sql.SQLException: JZ006: Caught IOException: java.io.IOException: JZ0T3: Read operation timed out." will appear in case of memory leaks and JBoss will identify and log into JBoss log file server.log.

I have pasted the content of JBoss log file server.log. There is no such WARN entry in it around an hour time where concern (thread became inactive) happened. I have also the highlighted the problematic thread in BOLD. Here, from that particular line of log, I could understand the thread resumes again after an hour and since transaction already died, applying COMMIT or ROLLBACK on the inactive transaction log says "ARJUNA-16063 The transaction is not active!". Hence, this is related to the THREAD GETTING INACTIVE.

Could you please give me a hint of what can cause the thread to be suspended from JBoss as none of the thread is suspended from the code.

2017-01-09 10:06:49,253 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA-12117 TransactionReaper::check timeout for TX 0:ffff0a0a9682:126a:586b8456:1026bd in state  RUN

2017-01-09 10:06:49,253 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12095 Abort of action id 0:ffff0a0a9682:126a:586b8456:1026bd invoked while multiple threads active within it.

2017-01-09 10:06:49,253 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12108 CheckedAction::check - atomic action 0:ffff0a0a9682:126a:586b8456:1026bd aborting with 1 threads active!

2017-01-09 10:06:49,257 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12121 TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,jboss] successfully canceled TX 0:ffff0a0a9682:126a:586b8456:1026bd

2017-01-09 10:08:38,723 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA-12117 TransactionReaper::check timeout for TX 0:ffff0a0a9682:126a:586b8456:10286e in state  RUN

2017-01-09 10:08:38,724 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12095 Abort of action id 0:ffff0a0a9682:126a:586b8456:10286e invoked while multiple threads active within it.

2017-01-09 10:08:38,724 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12108 CheckedAction::check - atomic action 0:ffff0a0a9682:126a:586b8456:10286e aborting with 1 threads active!

2017-01-09 10:08:38,730 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12121 TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,jboss] successfully canceled TX 0:ffff0a0a9682:126a:586b8456:10286e

2017-01-09 10:09:10,296 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA-12117 TransactionReaper::check timeout for TX 0:ffff0a0a9682:126a:586b8456:1028a4 in state  RUN

2017-01-09 10:09:10,296 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12095 Abort of action id 0:ffff0a0a9682:126a:586b8456:1028a4 invoked while multiple threads active within it.

2017-01-09 10:09:10,296 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12108 CheckedAction::check - atomic action 0:ffff0a0a9682:126a:586b8456:1028a4 aborting with 1 threads active!

2017-01-09 10:09:10,322 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12121 TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,jboss] successfully canceled TX 0:ffff0a0a9682:126a:586b8456:1028a4

2017-01-09 10:10:27,104 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA-12117 TransactionReaper::check timeout for TX 0:ffff0a0a9682:126a:586b8456:102943 in state  RUN

2017-01-09 10:10:27,104 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12095 Abort of action id 0:ffff0a0a9682:126a:586b8456:102943 invoked while multiple threads active within it.

2017-01-09 10:10:27,105 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12108 CheckedAction::check - atomic action 0:ffff0a0a9682:126a:586b8456:102943 aborting with 1 threads active!

2017-01-09 10:10:27,109 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12121 TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,jboss] successfully canceled TX 0:ffff0a0a9682:126a:586b8456:102943

2017-01-09 10:20:35,507 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA-12117 TransactionReaper::check timeout for TX 0:ffff0a0a9682:126a:586b8456:1031c3 in state  RUN

2017-01-09 10:20:35,508 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12095 Abort of action id 0:ffff0a0a9682:126a:586b8456:1031c3 invoked while multiple threads active within it.

2017-01-09 10:20:35,508 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12108 CheckedAction::check - atomic action 0:ffff0a0a9682:126a:586b8456:1031c3 aborting with 1 threads active!

2017-01-09 10:20:35,515 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12121 TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,jboss] successfully canceled TX 0:ffff0a0a9682:126a:586b8456:1031c3

2017-01-09 10:22:15,490 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA-12117 TransactionReaper::check timeout for TX 0:ffff0a0a9682:126a:586b8456:103286 in state  RUN

2017-01-09 10:22:15,490 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12095 Abort of action id 0:ffff0a0a9682:126a:586b8456:103286 invoked while multiple threads active within it.

2017-01-09 10:22:15,490 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12108 CheckedAction::check - atomic action 0:ffff0a0a9682:126a:586b8456:103286 aborting with 1 threads active!

2017-01-09 10:22:15,494 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12121 TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,jboss] successfully canceled TX 0:ffff0a0a9682:126a:586b8456:103286

2017-01-09 10:22:43,573 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA-12117 TransactionReaper::check timeout for TX 0:ffff0a0a9682:126a:586b8456:1032bf in state  RUN

2017-01-09 10:22:43,573 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12095 Abort of action id 0:ffff0a0a9682:126a:586b8456:1032bf invoked while multiple threads active within it.

2017-01-09 10:22:43,573 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12108 CheckedAction::check - atomic action 0:ffff0a0a9682:126a:586b8456:1032bf aborting with 1 threads active!

2017-01-09 10:22:43,592 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12121 TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,jboss] successfully canceled TX 0:ffff0a0a9682:126a:586b8456:1032bf

2017-01-09 10:32:20,020 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA-12117 TransactionReaper::check timeout for TX 0:ffff0a0a9682:126a:586b8456:103815 in state  RUN

2017-01-09 10:32:20,020 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12095 Abort of action id 0:ffff0a0a9682:126a:586b8456:103815 invoked while multiple threads active within it.

2017-01-09 10:32:20,020 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12108 CheckedAction::check - atomic action 0:ffff0a0a9682:126a:586b8456:103815 aborting with 1 threads active!

2017-01-09 10:32:20,029 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12121 TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,jboss] successfully canceled TX 0:ffff0a0a9682:126a:586b8456:103815

2017-01-09 10:42:35,599 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA-12117 TransactionReaper::check timeout for TX 0:ffff0a0a9682:126a:586b8456:104196 in state  RUN

2017-01-09 10:42:35,599 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12095 Abort of action id 0:ffff0a0a9682:126a:586b8456:104196 invoked while multiple threads active within it.

2017-01-09 10:42:35,599 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12108 CheckedAction::check - atomic action 0:ffff0a0a9682:126a:586b8456:104196 aborting with 1 threads active!

2017-01-09 10:42:35,608 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12121 TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,jboss] successfully canceled TX 0:ffff0a0a9682:126a:586b8456:104196

2017-01-09 10:42:53,895 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA-12117 TransactionReaper::check timeout for TX 0:ffff0a0a9682:126a:586b8456:104250 in state  RUN

2017-01-09 10:42:53,895 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12095 Abort of action id 0:ffff0a0a9682:126a:586b8456:104250 invoked while multiple threads active within it.

2017-01-09 10:42:53,895 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12108 CheckedAction::check - atomic action 0:ffff0a0a9682:126a:586b8456:104250 aborting with 1 threads active!

2017-01-09 10:42:53,906 WARN  [com.arjuna.ats.arjuna] (Transaction Reaper Worker 0) ARJUNA-12121 TransactionReaper::doCancellations worker Thread[Transaction Reaper Worker 0,5,jboss] successfully canceled TX 0:ffff0a0a9682:126a:586b8456:104250

2017-01-09 11:05:48,213 WARN  [com.arjuna.ats.arjuna] (pool-63-thread-6) ARJUNA-12077 Abort called on already aborted atomic action 0:ffff0a0a9682:126a:586b8456:1026bd

2017-01-09 11:05:48,304 WARN  [com.arjuna.ats.arjuna] (pool-63-thread-14) ARJUNA-12077 Abort called on already aborted atomic action 0:ffff0a0a9682:126a:586b8456:10286e

2017-01-09 11:05:48,304 WARN  [com.arjuna.ats.arjuna] (ajp-127.0.0.1-8009-3) ARJUNA-12077 Abort called on already aborted atomic action 0:ffff0a0a9682:126a:586b8456:102943

2017-01-09 11:05:48,306 WARN  [com.arjuna.ats.arjuna] (ajp-127.0.0.1-8009-11) ARJUNA-12077 Abort called on already aborted atomic action 0:ffff0a0a9682:126a:586b8456:1028a4

2017-01-09 11:05:48,535 WARN  [com.arjuna.ats.arjuna] (ajp-127.0.0.1-8009-1) ARJUNA-12077 Abort called on already aborted atomic action 0:ffff0a0a9682:126a:586b8456:1031c3

2017-01-09 11:05:48,535 WARN  [com.arjuna.ats.arjuna] (ajp-127.0.0.1-8009-2) ARJUNA-12077 Abort called on already aborted atomic action 0:ffff0a0a9682:126a:586b8456:103286

2017-01-09 11:05:53,531 WARN  [com.arjuna.ats.arjuna] (ajp-127.0.0.1-8009-5) ARJUNA-12077 Abort called on already aborted atomic action 0:ffff0a0a9682:126a:586b8456:1032bf

2017-01-09 11:07:48,216 WARN  [com.arjuna.ats.arjuna] (ajp-127.0.0.1-8009-9) ARJUNA-12077 Abort called on already aborted atomic action 0:ffff0a0a9682:126a:586b8456:103815

2017-01-09 11:08:30,027 WARN  [com.arjuna.ats.arjuna] (ajp-127.0.0.1-8009-12) ARJUNA-12077 Abort called on already aborted atomic action 0:ffff0a0a9682:126a:586b8456:104196

[andey]

Typically errors like this where a component tries to work with a transaction and is told, "The transaction is not active!" are caused by a transaction timeout.  When a transaction times out the transaction manager rolls it back asynchronously and then when a compontent tries to access the transaction again (e.g. to commit it or roll it back) it won't be able to according to the JTA spec.   In any case, clearly something has caused the transaction to be aborted because the log says, "Abort called on already aborted atomic action 0:ffff0a0a9682:126a:586b8456:1026bd."

It does appear that there are transaction timeout issues. Only the developers can say whether the time that the process is taking is expected or not. If it is expected then they would need to extend the transaction timeout for the process, if it isn't then they will need to investigate why the transaction is taking so long.

"ARJUNA012117" indicate transactions that are running longer than the configured timeout period and are being aborted. This could be indicative of anything from database server locking or database server performance problems to problems with memory or CPU on the application server that slows down individual transactions. If the load exceeds the connection pool size or if connections have been leaked you may also find application logic running more slowly than it should.

There are multiple potential causes for long running transactions including the following:

1#High load on the application server or database

2#Application logic that takes a long time to complete during a transaction

3#Database queries that run longer than the configured transaction timeout

4#Database blocks due to contention with other transactions (internal or external to JBoss) for table or row locks

5#General database performance problems

These messages indicate that a transaction is timing out. The WARN is issued by an asynchronous JBossTS transaction "reaper" thread that aborts the timed-out transaction. There are a few ways to address this issue:

Refactor transaction logic to perform less work and thereby reduce the likelihood of a time-out.

Verify integrity of the transactional resources and their environment (e.g. a database table may need an index, network connection may be slow, etc.).

Increase the default transaction timeout value.

Ensure that suitable memory, network bandwidth, etc. are available for the system load and traffic

Resolve inefficiencies in application logic

Address database locking contention

Perform database tuning per vendor recommendations.

The startup bean initializes multiple caches in parallel by submitting Callable jobs to an asynchronous bean for execution. The cache initialization job may or may not call a third bean in order to initialize the cache. For example , the default transaction timeout is set at 30 seconds in standalone.xml. The transaction timeout for the startup bean and AsyncEJB is set to 150 seconds. The cache initialization takes place in WorkerEJB, which runs for 50 seconds.

Need to set the transaction timeout annotation @TransactionTimeout(value = <value> , unit = TimeUnit.SECONDS) on the AsyncEJB, thus transactions would time out in this bean.

Need to remove the annotation @TransactionAttribute(TransactionAttributeType.SUPPORTS) on AsyncEJB.

It is always recommended to try and keep transaction times as small as possible, but if this is not possible, then to extend the timeout for the long running process only rather than extending the default timeout. However, how you extend the timeout for the process will depend on how it is implemented.

[sridharthiyagarajan]

Many thanks for the response. I am checking on your valuable comments and get back to you. I know about JMX console and apart from it, could you please suggest any free monitoring tool for JBoss-6.1.0 AS where I can monitor open thread status, connection status.

Is there any possibility to log thread state alone in a separate log file by adding a logging configuration ?

[andey]

>>Is there any possibility to log thread state alone in a separate log file by adding a logging configuration ?

I'm not sure thread state in alone in a separate log file, but you can see all the TX related information in server.log file itself.

Yes, you can enable JCA TRACE level logging category with the below parameters :

================

    org.jboss.jca

    org.jboss.as.connector

    com.arjuna

======================

~~~

  <logger category="com.arjuna">
  <level name="TRACE"/>
  </logger>
  <logger category="org.jboss.jca">
  <level name="TRACE"/>
  </logger>
  <logger category="org.jboss.as.connector">
  <level name="TRACE"/>
  </logger>

~~~