5 Replies Latest reply on Jan 19, 2017 4:59 AM by Anup Dey

    Bean Managed transaction, commit issue is getting delayed

    Manohar M Newbie

      Hello All,

       

      We are using Jboss 6.1.0 final on Suse 12 with Sybase 15.5 (On some sites) and 16 (On some sites) as the database.

      Also, we are using JConnect 16 with sybase.

       

      By default, we are switching off autocommit to false.

       

      We have a strange problem that, Within bean managed transaction, there are many SQL statements that are run and all are successfully completed. Within this transaction, there are some update queries as well.

      When we compare line by line code along with the logs, we could see that, the last statement in the log reflects running a successfully a SELECT query.

      Right after this statement, next statement in the code is to issue a committx statement which in our case takes too much time and after lets say 15 min, committx is issued and because of the transaction timeout, its rolledback.

       

      Correspondingly, in this idle period, when we check the statements executed by the database connection, there is none and state of the connection is AWAITING_COMMAND.

       

      Its a chained transaction which is run in the database holding locks on multiple tables. Unless, this transaction is committed, these locks will not be released and hence its creating lot of waiting time for other clients.

       

      I can understand, if the commit is issued and this takes time, then, there could be blocking from the database and hence, commit is taking more time.

      But, here, its very strange that, there are no other statements that are being executed by the connection, but still, commit is not issued.

       

       

      2015-12-22 15:17:11,904 DEBUG [DAOClass] [EventId: ] [pool-69-thread-26] ['dao.rowsProcessed']: 1 rows processed

      2015-12-22 15:33:15,501 DEBUG [BeanUtils] [EventId: ] [pool-69-thread-26] commitTx

      2015-12-22 15:33:15,502 ERROR [BeanUtils] [EventId: ] [pool-69-thread-26] commitTx() failedARJUNA-16063 The transaction is not active!

       

      Anybody has faced similar problems earlier or would be really great if any of you can guide on how this problem can be debugged.

       

      Rgds

      Manohar

        • 1. Re: Bean Managed transaction, commit issue is getting delayed
          Anup Dey Apprentice

          Hi

           

          The message shows that you do not have an active transaction while you are trying to remove content from cache. The transaction associated with current thread has already been committed.

           

          The transaction associated with the current thread has already been committed when the application is trying to make the call to JBoss Cache, therefore it is unable to join the transaction.

           

          The issue is normally caused by a transaction reaching it's timeout value. So you may be increase the tx timeout.

           

          When the transaction times out and is aborted by the transaction reaper, it is the responsibility of the application to diss-associate the transaction from the thread. You are trying to do that with the session.getTransaction().rollback().

           

          This happens because the afterTransactionCompletion callback during the Transaction Reapers cancellation process sets the hibernate transaction in the JDBCContext to null. So in the catch block, when you try and get a transaction again, the JDBCContext has none so creates a new one that has not started

           

          So it may be that the application logic is correctly handling the scenario in this case

          • 2. Re: Bean Managed transaction, commit issue is getting delayed
            Manohar M Newbie

            Thanks Anup for the response. Pls check my response below.

             

            The message shows that you do not have an active transaction while you are trying to remove content from cache. The transaction associated with current thread has already been committed.

            --> This is not the case. Because, as I said earlier, within the transaction, thread which is responsible to commit the transaction itself has not executed the commit and its blocked. What are the possibilities that this thread can be blocked inspite of completing all the statement execution is the question that I've.

             

            Increasing the timeout will actually cause all the other client application to hang for more time.

             

             

            • 3. Re: Bean Managed transaction, commit issue is getting delayed
              Anup Dey Apprentice

              Hi,

               

              Attach full server.log file showing the issue in full stack trace?

              • 4. Re: Bean Managed transaction, commit issue is getting delayed
                Manohar M Newbie

                Due to data constraints, i'm unable to upload complete log.

                But, I'm mentioning key statements and sequence of events:

                 

                We import a message from external system:

                 

                2015-12-22 15:17:11,858 INFO  [XMLImporter] [EventId: ] [pool-69-thread-26] ['openlink.import.receivedMsg']: The OL message has been received

                2015-12-22 15:17:11,859 INFO  [XMLImporter] [EventId: ] [pool-69-thread-26] ['openlink.import.completeMsg']: The imported message is :

                <message>

                  <type>import</type>

                  <event>updatevisit</event>

                  <messageid>201512221517085468.0</messageid>

                  <patient>

                    ...

                  ...

                  ...

                  </patient>

                </message>

                Then, as you can observe, processing of this message has been started by pool-69-thread-26.

                 

                2015-12-22 15:17:11,861 DEBUG [SASFacadeBean] [EventId: ] [pool-69-thread-26] UPDATE_VISIT

                2015-12-22 15:17:11,862 DEBUG [CommSubBean] [EventId: ] [pool-69-thread-26] updateVisit()

                2015-12-22 15:17:11,862 DEBUG [BeanUtils] [EventId: ] [pool-69-thread-26] beginTx

                2015-12-22 15:17:11,862 DEBUG [BeanUtils] [EventId: ] [pool-69-thread-26] getTx

                2015-12-22 15:17:11,862 DEBUG [BeanUtils] [EventId: ] [pool-69-thread-26] status: STATUS_ACTIVE

                2015-12-22 15:17:11,862 DEBUG [SASConnection] [EventId: ] [pool-69-thread-26] ['dao.connectionInit']: SASConnection init with db SybaseDB

                2015-12-22 15:17:11,863 DEBUG [SASConnection] [EventId: ] [pool-69-thread-26] ['dao.currentTransIL']: Current TransactionIsolation level: 2

                2015-12-22 15:17:11,863 DEBUG [SASConnection] [EventId: ] [pool-69-thread-26] ['dao.currentAutocommit']: Current Autocommit: false

                2015-12-22 15:17:11,864 DEBUG [DAOOpenAspect] [EventId: ] [pool-69-thread-26] DAO opened!

                Transaction has been started from EJB.

                 

                2015-12-22 15:17:11,865 DEBUG [DBBaseDAO] [EventId: ] [pool-69-thread-26] SQL query: SELECT DISTINCT patient.orig_pat_name AS "patient.orig_pat_name",patient.pat_ckey AS "PatCKey",patient.pat_status AS "patient.pat_status" FROM patient WHERE (patient.ris_pat_id='abcd1234' AND patient.orig_pat_name='Test123_Test23')

                2015-12-22 15:17:11,866 DEBUG [DBBaseDAO] [EventId: ] [pool-69-thread-26] ['dao.rowsProcessed']: 1 rows processed

                Some of the select query is successfully processed. Also, as shown below, there is an update statement which is run successfully:

                 

                2015-12-22 15:17:11,877 DEBUG [DBBaseDAO] [EventId: ] [pool-69-thread-26] SQL : UPDATE patient SET blavbla='blabla' WHERE patient.pat_ckey=43490

                2015-12-22 15:17:11,880 DEBUG [DBBaseDAO] [EventId: ] [pool-69-thread-26] ['dao.rowsUpdated']: 1 rows were updated.

                 

                Then as last statement within this transaction, a select query is executed:

                 

                2015-12-22 15:17:11,903 DEBUG [DBBaseDAO] [EventId: ] [pool-69-thread-26] SQL query: SELECT test_pacs.long_descr  FROM test_pacs WHERE test_pacs.long_descr NOT LIKE '#%'

                2015-12-22 15:17:11,904 DEBUG [DBBaseDAO] [EventId: ] [pool-69-thread-26] ['dao.rowsProcessed']: 1 rows processed

                this statement execution was completed at 15:17:11,904

                 

                And as immediate next step, commit is to be issued and we could see that, it has been done only after 16 minutes and hence transaction is timed out. Exact problem is this. Unless this transaction is committed, all the locks held by this transaction will not be release thereby causing other client applications to hang.

                 

                2015-12-22 15:33:15,501 DEBUG [BeanUtils] [EventId: ] [pool-69-thread-26] commitTx

                2015-12-22 15:33:15,502 ERROR [BeanUtils] [EventId: ] [pool-69-thread-26] commitTx() failedARJUNA-16063 The transaction is not active!

                2015-12-22 15:33:15,503 DEBUG [BeanUtils] [EventId: ] [pool-69-thread-26] rollbackTx

                2015-12-22 15:33:15,503 ERROR [BeanUtils] [EventId: ] [pool-69-thread-26] rollbackTx() java.lang.IllegalStateException - BaseTransaction.rollback - ARJUNA-16074 no transaction!

                I'm unable to interpret as to why this transaction was hanging and commit was not issued. Had it been the case that, commit was issued and then if it was taking time, it could have been a database lock which is causing this. But, here, commit statement itself is not getting executed for 16 min.

                 

                I've also enabled transaction logs to be enabled on the production system. As and when I get this information, I can share that.

                 

                Any help is greatly appreciated.

                 

                Rgds

                Manohar

                • 5. Re: Bean Managed transaction, commit issue is getting delayed
                  Anup Dey Apprentice

                  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 component 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