1 2 Previous Next 20 Replies Latest reply on Nov 18, 2019 7:15 AM by ochaloup

    Aborting with 1 threads active

    f28b1edf
    f28b1edf Sep 11, 2008 4:34 AM

      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

      • 33029 Views
      • Tags:
        • 1. Re: Aborting with 1 threads active
          marklittle
          marklittle Sep 11, 2008 7:00 AM (in response to f28b1edf)

          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?

            • Actions
          • 2. Re: Aborting with 1 threads active
            f28b1edf
            f28b1edf Sep 15, 2008 11:38 PM (in response to f28b1edf)

            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!


              • Actions
            • 3. Re: Aborting with 1 threads active
              f28b1edf
              f28b1edf Sep 16, 2008 4:49 AM (in response to f28b1edf)

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

                • Actions
              • 4. Re: Aborting with 1 threads active
                marklittle
                marklittle Sep 16, 2008 9:11 AM (in response to f28b1edf)

                Yes, that's right.

                  • Actions
                • 5. Re: Aborting with 1 threads active
                  f28b1edf
                  f28b1edf Dec 1, 2008 8:47 AM (in response to f28b1edf)

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

                    • Actions
                  • 6. Re: Aborting with 1 threads active
                    marklittle
                    marklittle Dec 1, 2008 9:02 AM (in response to f28b1edf)

                    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.

                      • Actions
                    • 7. Re: Aborting with 1 threads active
                      f28b1edf
                      f28b1edf Dec 1, 2008 9:24 AM (in response to f28b1edf)

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

                        • Actions
                      • 8. Re: Aborting with 1 threads active
                        marklittle
                        marklittle Dec 1, 2008 10:01 AM (in response to f28b1edf)

                        "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.

                          • Actions
                        • 9. Re: Aborting with 1 threads active
                          f28b1edf
                          f28b1edf Dec 1, 2008 12:54 PM (in response to f28b1edf)

                          Ok, thank you :)

                            • Actions
                          • 10. Re: Aborting with 1 threads active
                            mazz
                            mazz Dec 1, 2008 2:54 PM (in response to f28b1edf)

                            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.

                              • Actions
                            • 11. Re: Aborting with 1 threads active
                              marklittle
                              marklittle Dec 4, 2008 2:41 AM (in response to f28b1edf)

                               

                              "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 ;-)

                                • Actions
                              • 12. Re: Aborting with 1 threads active
                                mazz
                                mazz Dec 7, 2008 12:13 AM (in response to f28b1edf)

                                 

                                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.

                                  • Actions
                                • 13. Re: Aborting with 1 threads active
                                  born_free
                                  born_free Jan 27, 2009 9:21 PM (in response to f28b1edf)

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

                                    • Actions
                                  • 14. Re: Aborting with 1 threads active
                                    f28b1edf
                                    f28b1edf Mar 12, 2009 1:10 PM (in response to f28b1edf)

                                    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.


                                      • Actions
                                    1 2 Previous Next