1 2 Previous Next 16 Replies Latest reply on May 21, 2009 4:14 AM by Jana -

    Aborting with 1 threads active

    Jana - Newbie

      Hi,
      from time to time our log file ends with

      WARN : [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id 7f000002:a108:48b40e06:282b06e invoked while multiple threads active within it.
      WARN : [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action 7f000002:a108:48b40e06:282b06e aborting with 1 threads active!

      and nothing works until JBoss restart. We tried some googling and so we found e.g.
      https://jira.jboss.org/jira/browse/JBAS-4493
      https://jira.jboss.org/jira/browse/JBAS-4481
      http://wiki.jboss.org/wiki/TxMultipleThreads
      We tried some changes, we checked our code that we do close all connections in finally blocks, but nothing helped. Could someone please suggest any way how to solve this? We use JBoss 4.2.2, EJB3
      Thanks, Jana

        • 1. Re: Aborting with 1 threads active
          Mark Little Master

          Turn on debugging (see the docs for how to do that). Then you'll see what transactions are created and when they are terminated. BTW, I assume you have ruled out timeouts as the wiki page mentions?

          • 2. Re: Aborting with 1 threads active
            Jana - Newbie

            Thank you for reply. I've changed Threshold value from INFO to DEBUG in jboss-log4j.xml appender tag, but it is not the right place i guess... Could you please give me link to docs?
            There is nothing more about arjuna in the log file than this:

            DEBUG: Periodic recovery - first pass <Tue, 16 Sep 2008 05:11:36>
            DEBUG: StatusModule: first pass
            DEBUG: [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_3] - TORecoveryModule - first pass
            DEBUG: [com.arjuna.ats.internal.jta.recovery.info.firstpass] Local XARecoveryModule - first pass
            DEBUG: Periodic recovery - second pass <Tue, 16 Sep 2008 05:11:46>
            DEBUG: AtomicActionRecoveryModule: Second pass
            DEBUG: [com.arjuna.ats.internal.txoj.recovery.TORecoveryModule_6] - TORecoveryModule - second pass
            DEBUG: [com.arjuna.ats.internal.jta.recovery.info.secondpass] Local XARecoveryModule - second pass
            DEBUG: Periodic recovery - first pass <Tue, 16 Sep 2008 05:13:46>
            
            WARN : [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id 7f000002:ac37:48cf23c7:18810 invoked while multiple threads active within it.
            WARN : [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action 7f000002:ac37:48cf23c7:18810 aborting with 1 threads active!
            


            • 3. Re: Aborting with 1 threads active
              Jana - Newbie

              so i found http://www.jboss.org/jbosstm/docs/4.2.3/manuals/html/jta/AdministrationGuide.html (is that right?)
              I'll do some more research in a few days...

              • 4. Re: Aborting with 1 threads active
                Mark Little Master

                Yes, that's right.

                • 5. Re: Aborting with 1 threads active
                  Jana - Newbie

                  With the debugging on the log file is too big...
                  I did grep one action id and the result is this:

                  03:37:50,444 arjLogger DEBUG: BasicAction::Begin() for action-id 7f000002:cfb:492a03da:548f6
                  03:37:50,444 arjLogger DEBUG: BasicAction::actionInitialise() for action-id 7f000002:cfb:492a03da:548f6
                  03:37:50,444 arjLogger DEBUG: ActionHierarchy::add(7f000002:cfb:492a03da:548f6, 1)
                  03:37:50,444 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss]
                  03:37:50,444 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss] result = true
                  03:37:50,444 arjLogger DEBUG: TransactionReaper::insert ( BasicAction: 7f000002:cfb:492a03da:548f6 status: ActionStatus.RUNNING, 300 )
                  03:37:50,444 arjLogger DEBUG: ReaperElement::ReaperElement ( BasicAction: 7f000002:cfb:492a03da:548f6 status: ActionStatus.RUNNING, 300 )
                  03:37:50,461 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:d7
                  03:37:50,461 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:d7 result = true
                  03:37:50,461 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss]
                  03:37:50,461 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss] result = true
                  03:37:57,162 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:d7
                  03:37:57,162 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:d7 result = true
                  03:37:57,162 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss]
                  03:37:57,162 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss] result = true
                  03:37:57,162 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:d7
                  03:37:57,163 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:d7 result = true
                  03:37:57,163 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss]
                  03:37:57,163 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action 7f000002:cfb:492a03da:548f6 adding Thread[http-0.0.0.0-80-207,5,jboss] result = true
                  03:42:50,462 arjLogger DEBUG: BasicAction::Abort() for action-id 7f000002:cfb:492a03da:548f6
                  03:42:50,462 arjLoggerI18N WARN : [com.arjuna.ats.arjuna.coordinator.BasicAction_58] - Abort of action id 7f000002:cfb:492a03da:548f6 invoked while multiple threads active within it.
                  03:42:50,462 arjLoggerI18N WARN : [com.arjuna.ats.arjuna.coordinator.CheckedAction_2] - CheckedAction::check - atomic action 7f000002:cfb:492a03da:548f6 aborting with 1 threads active!
                  03:42:50,462 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_63] - BasicAction::removeAllChildThreads () action 7f000002:cfb:492a03da:548f6 removing Thread[http-0.0.0.0-80-207,5,jboss]
                  03:42:50,462 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:10a
                  03:42:50,462 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action 7f000002:cfb:492a03da:548f6 removing TSThread:10a result = true
                  03:42:50,464 arjLogger DEBUG: TransactionReaper::remove ( BasicAction: 7f000002:cfb:492a03da:548f6 status: ActionStatus.ABORTED )
                  03:42:50,464 arjLoggerI18N DEBUG: [com.arjuna.ats.arjuna.coordinator.TransactionReaper_3] - TransactionReaper::check - rollback for 7f000002:cfb:492a03da:548f6
                  

                  But now i'm lost again...

                  • 6. Re: Aborting with 1 threads active
                    Mark Little Master

                    Yes, this looks like a timeout as I mentioned in September. So you need to figure out why the transaction is "blocked" and being timed out.

                    • 7. Re: Aborting with 1 threads active
                      Jana - Newbie

                      I know, but 300 seconds is a long time...
                      The problem happens only sometimes, eg. after a week or longer.

                      • 8. Re: Aborting with 1 threads active
                        Mark Little Master

                        "300 seconds is a long time..." is a subjective statement. For the Methuselah Tree (http://www.waymarking.com/waymarks/WMQDF) it's nothing. Whereas for the mayfly it can be an eternity.

                        It's obvious that you have a transaction that is "blocking" on a resource (maybe a locked db table?) You'd have to try stepping through the running system and identifying what's happening in that specific transaction though to go further.

                        • 9. Re: Aborting with 1 threads active
                          Jana - Newbie

                          Ok, thank you :)

                          • 10. Re: Aborting with 1 threads active
                            mazz Master

                            BTW: I wrote a CheckedAction class that will log the actual stack trace of the thread(s) that are active when a tx aborts (e.g. when it times out). This will let you know exactly what was working in that tx at the time of the time out (I've found that I would like to see this information, rather than the rather uninformative "CheckedAction::check - atomic action aborting with 1 threads active!" message). e.g. You can see exactly what part of your code was blocked.

                            Note: this will ONLY log stack traces of threads whose tx's timed out (you won't get flooded with information unless and until tx's time out or are aborted for some reason by the TM)

                            See the inner class found at the bottom of this:

                            http://svn.rhq-project.org/repos/rhq/trunk/modules/enterprise/server/jar/src/main/java/org/rhq/enterprise/server/common/TransactionInterruptInterceptor.java

                            The parent class is an EJB3 interceptor that shows you how you can install this CheckedAction class into the current thread's associated transaction (using BasicAction.Current).

                            This custom CheckedAction also has the ability to issue a Thread.interrupt to the threads that are active (to possibly wake them up and let them know their tx timed out). But that feature is orthogonal to the logging feature.

                            • 11. Re: Aborting with 1 threads active
                              Mark Little Master

                               

                              "mazz" wrote:

                              This custom CheckedAction also has the ability to issue a Thread.interrupt to the threads that are active (to possibly wake them up and let them know their tx timed out). But that feature is orthogonal to the logging feature.


                              Yes, that's one of the advantages of being able to override this on an application specific basis, but we definitely won't do that by default since it can be dangerous ;-) Think of the TM as a dumb overlord who always does the safest thing possible. But we provide you the rope if you know what I mean ;-)

                              • 12. Re: Aborting with 1 threads active
                                mazz Master

                                 

                                but we definitely won't do that by default since it can be dangerous ;-) Think of the TM as a dumb overlord who always does the safest thing possible. But we provide you the rope if you know what I mean ;-)


                                Absolutely, in fact, even that custom code I wrote doesn't do it by default :) I don't trust myself with the rope. But for those instances where interrupting the thread is appropriate, adding a simple annotation on the SLSB method will do the trick.

                                • 13. Re: Aborting with 1 threads active
                                  Born Free Newbie

                                  We are also facing the same issue, in our case we are using ejb 2.0, will this help in our case

                                  • 14. Re: Aborting with 1 threads active
                                    Jana - Newbie

                                    mazz, thank you a lot, i did use you code and i got this:

                                    java.lang.Throwable: STACK TRACE OF ACTIVE THREAD IN TERMINATING TRANSACTION
                                     at java.lang.Object.wait(Native Method)
                                     at org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock.waitForTx(QueuedPessimisticEJBLock.java:323)
                                     at org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock.doSchedule(QueuedPessimisticEJBLock.java:230)
                                     at org.jboss.ejb.plugins.lock.QueuedPessimisticEJBLock.schedule(QueuedPessimisticEJBLock.java:194)
                                     at org.jboss.ejb.plugins.EntityLockInterceptor.invoke(EntityLockInterceptor.java:100)

                                    I have found some bug report https://jira.jboss.org/jira/browse/JBAS-6348, can it be related? I'm stuck again.


                                    1 2 Previous Next