1 2 Previous Next 19 Replies Latest reply on Dec 29, 2008 7:21 AM by Andrew Dinn

    find out how many resources are enlisted in tx

    mazz Master

      How can I find out how many resources are enlisted in a transaction?

      I have the current transaction via "BasicAction.Current()". In a debugger, I see this object has a protected member "pendingList" of type "com.arjuna.ats.arjuna.coordinator.RecordList". I think this is what I want - that RecordList has a "noEntries" field that looks to be the number of XAResourceRecord items in the list. But its not accessible via a public API that I can see. Is there some way that I can know how many XA resources have been enlisted in the tx?

      What I *really* want to know is if my transaction is going to use 2PC semantics (i.e. will it create a tx log in the object store and will it attempt to recover that tx if it fails??). If there is some way to do that, that would be what I really want to do.

      Because JBossTM will never use 2PC semantics if only a single resource is enlisted (even if that resource is an XAResource), then knowing that a transaction has 1 enlisted resource will let me know that my object store will not get a log written to it and 2PC is not going to be used for that transaction (and hence why my original question was asked - "how many resources are enlisted in the tx").

      Why I am doing this is I have an EJB3 interceptor injected in all of my SLSB methods that I want to use while debugging - I want to trap and log all the times I'm creating a transaction that actually needs to use 2PC (i.e. which tx's are actually enlisting more than one resource and which resources are they). This is going to help me determine where I actually need 2PC and where I do not (for tuning purposes and other things).

        • 1. Re: find out how many resources are enlisted in tx
          Mark Little Master

           

          "mazz" wrote:
          How can I find out how many resources are enlisted in a transaction?

          I have the current transaction via "BasicAction.Current()". In a debugger, I see this object has a protected member "pendingList" of type "com.arjuna.ats.arjuna.coordinator.RecordList". I think this is what I want - that RecordList has a "noEntries" field that looks to be the number of XAResourceRecord items in the list. But its not accessible via a public API that I can see.


          Yes, that's because it's meant to be used only internally. We're definitely not going to change that because, as they say, 'here be dragons!'


          Is there some way that I can know how many XA resources have been enlisted in the tx?


          There's no standard way to do this. Plus those participants aren't necessarily XA participants. I assume you're using the term XA to mean 2PC-aware?


          What I *really* want to know is if my transaction is going to use 2PC semantics (i.e. will it create a tx log in the object store and will it attempt to recover that tx if it fails??). If there is some way to do that, that would be what I really want to do.


          Well that's not got everything to do with the number of resources anyway. For instance, if you've got 1000 participants registered and they all return READONLY during prepare then you won't get a log written.


          Because JBossTM will never use 2PC semantics if only a single resource is enlisted (even if that resource is an XAResource), then knowing that a transaction has 1 enlisted resource will let me know that my object store will not get a log written to it and 2PC is not going to be used for that transaction (and hence why my original question was asked - "how many resources are enlisted in the tx").


          Yes, but like I just pointed out, knowing that there are N > 1 participants doesn't help you there either. All you'll know is that we MAY write a log, but you can't tell until after the prepare phase has completed.


          Why I am doing this is I have an EJB3 interceptor injected in all of my SLSB methods that I want to use while debugging - I want to trap and log all the times I'm creating a transaction that actually needs to use 2PC (i.e. which tx's are actually enlisting more than one resource and which resources are they). This is going to help me determine where I actually need 2PC and where I do not (for tuning purposes and other things).


          Not really going to help you unless you can always ensure that the participants returned by your datasources will always behave the same for each use. So, for example, the XAResources that don't return READONLY this time will continue not to return READONLY next time. If you can't ensure that then the metrics you obtain from one run will not be applicable for subsequent invocations.

          I'm not suggesting that you can't do what you want, but only that checking the number of participants isn't sufficient. You need something that has knowledge about whether or not the 2nd phase of 2PC is entered.

          The of course I ask: why do you care? If you need transactions then JBossTS will optimise using 1PC or readonly semantics correctly anyway and you won't get logs unless you really need them. That's the domain of the transaction service, not the application.

          • 2. Re: find out how many resources are enlisted in tx
            Mark Little Master

             

            "mazz" wrote:
            I think this is what I want - that RecordList has a "noEntries" field that looks to be the number of XAResourceRecord items in the list. But its not accessible via a public API that I can see.


            If you want to continue assuming that N > 1 resources means that a log will be written, then size() on RecordList returns you noEntries. But you shouldn't use it for the reasons mentioned already, plus the fact that BasicAction assumes it (or descendants) is the only user of RecordLists so it's not synchronized. So we should really go back to determining why you think that you can tune transactions out of the picture better than the transaction manager should be able to do.


            • 3. Re: find out how many resources are enlisted in tx
              mazz Master

               

              I ask: why do you care?


              Because I want to know what part of my application actually needs 2PC and what doesn't (to answer your other question, I am more interested in 2PC semantics than I am XA vs. non-XA). I want to know which transactions will write a tx log to the object store, which won't - which will be recoverable by the TM if it fails, and which will not be.

              For instance, if you've got 1000 participants registered and they all return READONLY during prepare then you won't get a log written.


              I'm not sure when, if ever, my XA resources would ever return READONLY in the prepare phase. I have a very "normal" (from a transactioning point of view) J2EE app running in JBossAS 4.2.1. It uses JMS (JBossMQ under the covers) along with EJB3 SLSBs. There are 2 datasources, one is a <xa-datasource> and the other <no-tx-datasource>. I am trying to trace/debug the places where I enlist more than one datasource and where I actually use 2PC semantics, and where I do not. I suspect (well, I pretty much know) that in only a very few places do I really need 2PC, but I want to run my server and actually know for sure, with runtime proof/logging, where and when I'm using 2PC and where/when I am not.

              why you think that you can tune transactions out of the picture better than the transaction manager should be able to do.


              It's not that I think I can tune them better than the TM, but I *do* want to verify that the TM actually does this (i.e. I want to see it for myself actually work :-)

              I want to "prove" to myself that the TM really does what I expect it to (specifically, not write tx logs to the object store and not perform 2PC when a single resource is enlisted in a tx; in addition to successfully performing recovery when I have two enlisted resources in a failed tx). I am very interested in the times when the object store gets written to for reasons I explain below.

              Why do I want to prove this to myself? Because in JBossAS 4.2.1 https://jira.jboss.org/jira/browse/JBTM-418 is broke
              and https://jira.jboss.org/jira/browse/JBTM-441 is broke. It's not that I lost faith in the TM, but since I have found problems in the TM and its JBossAS integration I no longer trust that I have it working unless I see it for myself during runtime. It will also convince me that I actually configured it properly and didn't foobar it myself.

              I deploy my own version of the recovery object now, so 441 really isn't an issue for me anymore; but the fact is that I was able to "break" the TM doing very basic and simplistic tests (shutdown and restart the DB while my app was running (JBTM-441); simply wait past the expiryScanInterval time (JBTM-418)). The major problem that these cause - once I have a failed transaction in the object store, it will be there forever and never go away and can never be recovered (short of me requiring an admin manually stop then restart the app - and even then I'm not sure). 418 means any tx that can never recover will never get removed from the object store/file system; 441 means that anytime I lose connectivity to the database, I will never be able to recover again unless an admin manually restarts the app. Combine the two and you get a very toxic situation - the object store grows unbounded filling up the file system and the recovery process fails every time it tries (every 2 minutes) which floods the log files with many TM error messages. This means an app cannot automatically recover from even the most basic of tx failures - that being a connection to the database breaking due to db or network failure (even if that failure lasts for a short as a couple of minutes).

              In summary, I need to prove to myself that I now have a fully functioning/patched JBossAS that really does have a working JBossTM in it. Tracking when/where I am using 2PC will help me in this (it can also help me figure out if I can somehow eliminate my need for 2PC - through refactoring of the code or whatnot).


              • 4. Re: find out how many resources are enlisted in tx
                Mark Little Master

                 

                "mazz" wrote:
                I ask: why do you care?


                Because I want to know what part of my application actually needs 2PC and what doesn't (to answer your other question, I am more interested in 2PC semantics than I am XA vs. non-XA).


                OK, so this is more for runtime debugging? Couldn't you just turn on debug ;-)? JBossTM has some pretty in-depth debugging that can be controlled to fine granularity (per method type basis if you really want to.)


                I want to know which transactions will write a tx log to the object store, which won't - which will be recoverable by the TM if it fails, and which will not be.


                I suppose what I'm still missing is whether (and why) you need to do this dynamically? Can't you just examine the debug trace after the fact?


                For instance, if you've got 1000 participants registered and they all return READONLY during prepare then you won't get a log written.


                I'm not sure when, if ever, my XA resources would ever return READONLY in the prepare phase. I have a very "normal" (from a transactioning point of view) J2EE app running in JBossAS 4.2.1. It uses JMS (JBossMQ under the covers) along with EJB3 SLSBs. There are 2 datasources, one is a <xa-datasource> and the other <no-tx-datasource>.


                Well any XAResource can return READONLY if it determines that the state it's controlling (nominally the work for which it's responsible) hasn't changed. I suspect that JBossMQ doesn't do much for this at all. But JBoss Messaging might and since it's the default JMS implementation these days it may be worth checking. Obviously other JMS implementations may have their quirks.


                I am trying to trace/debug the places where I enlist more than one datasource and where I actually use 2PC semantics, and where I do not.


                OK. Sounds good. Sounds like the trace/debug statements would be enough then?


                I suspect (well, I pretty much know) that in only a very few places do I really need 2PC, but I want to run my server and actually know for sure, with runtime proof/logging, where and when I'm using 2PC and where/when I am not.


                Great. In which case why not enable logging for FAC_ABSTRACT_REC and FAC_ATOMIC_ACTION? That way you'll only get logging from the coordinator and its participants. If you want to see the log being used then enable for FAC_OBJECT_STORE too. The Programmers Guide/Administrators Guide shows how to do this, but basically it's all based on bit codes so you can enable these concurrently whilst disabling everything else.


                why you think that you can tune transactions out of the picture better than the transaction manager should be able to do.


                It's not that I think I can tune them better than the TM, but I *do* want to verify that the TM actually does this (i.e. I want to see it for myself actually work :-)


                I may have been paranoid ;-)


                I want to "prove" to myself that the TM really does what I expect it to (specifically, not write tx logs to the object store and not perform 2PC when a single resource is enlisted in a tx; in addition to successfully performing recovery when I have two enlisted resources in a failed tx). I am very interested in the times when the object store gets written to for reasons I explain below.


                What, you don't trust us ;-) ?


                Why do I want to prove this to myself? Because in JBossAS 4.2.1 https://jira.jboss.org/jira/browse/JBTM-418 is broke
                and https://jira.jboss.org/jira/browse/JBTM-441 is broke. It's not that I lost faith in the TM, but since I have found problems in the TM and its JBossAS integration I no longer trust that I have it working unless I see it for myself during runtime. It will also convince me that I actually configured it properly and didn't foobar it myself.


                Sure, but one of those issues has been verified as fixed with tests and I think the other is done too similarly. Why not grab the entire QA suite? It is very informative :-) [No, I'm not being sarcastic, I honestly mean it.]


                I deploy my own version of the recovery object now, so 441 really isn't an issue for me anymore; but the fact is that I was able to "break" the TM doing very basic and simplistic tests (shutdown and restart the DB while my app was running (JBTM-441);


                Yes, the team have been concentrating on EAP 5 and AS 5 integration lately.


                simply wait past the expiryScanInterval time (JBTM-418)).


                And this one was fixed before you came across it ;-) It's not our fault the patch hadn't been incorporated (well, maybe it is ;-)


                The major problem that these cause - once I have a failed transaction in the object store, it will be there forever and never go away and can never be recovered (short of me requiring an admin manually stop then restart the app - and even then I'm not sure). 418 means any tx that can never recover will never get removed from the object store/file system;


                Well 418 doesn't change that statement - the log entry gets moved (previously it was erroneously copied), but it still stays within the object store.


                441 means that anytime I lose connectivity to the database, I will never be able to recover again unless an admin manually restarts the app. Combine the two and you get a very toxic situation - the object store grows unbounded filling up the file system and the recovery process fails every time it tries (every 2 minutes) which floods the log files with many TM error messages. This means an app cannot automatically recover from even the most basic of tx failures - that being a connection to the database breaking due to db or network failure (even if that failure lasts for a short as a couple of minutes).


                Which one of your resources is one-phase (db or jms)? In that case you don't get recovery for it anyway: it either commits or it rolls back, there's no in between situation.


                In summary, I need to prove to myself that I now have a fully functioning/patched JBossAS that really does have a working JBossTM in it. Tracking when/where I am using 2PC will help me in this (it can also help me figure out if I can somehow eliminate my need for 2PC - through refactoring of the code or whatnot).


                Well if the TM is doing its job then you shouldn't see much overhead at all when using a single resource and zero overhead when using no resources. So scoping work within a transaction in your case by default may be worth the trouble in the event things change that you didn't foresee.

                • 5. Re: find out how many resources are enlisted in tx
                  Mark Little Master

                  BTW, if you're just after verifying those issues then why not just modify one of the recovery examples from the recovery wiki page? It's fairly straightforward to make them such that they would trigger those situations, since neither of those issues are tied to the ATS integration. Yes, I know 441 is triggered by the ats integration db recovery resource, but you can easily create a stand-alone version.

                  • 6. Re: find out how many resources are enlisted in tx
                    Mark Little Master

                    Another BTW ... I'm on vacation for the next 2 weeks so if you're really nice I could do the above modification for you if you want ;-)

                    • 7. Re: find out how many resources are enlisted in tx
                      mazz Master

                       

                      "mark.little@jboss.com" wrote:
                      OK. Sounds good. Sounds like the trace/debug statements would be enough then?


                      Yes, I think so.

                      Great. In which case why not enable logging for FAC_ABSTRACT_REC and FAC_ATOMIC_ACTION? That way you'll only get logging from the coordinator and its participants. If you want to see the log being used then enable for FAC_OBJECT_STORE too. The Programmers Guide/Administrators Guide shows how to do this, but basically it's all based on bit codes so you can enable these concurrently whilst disabling everything else.


                      Sounds good - I wasn't aware of this in the docs, I will check it out.

                      What, you don't trust us ;-) ?


                      Only about as far as I can throw you. :) But, I must admit, I equally don't trust myself - to be honest, I have no idea what the hell I'm doing ;)

                      Which one of your resources is one-phase (db or jms)? In that case you don't get recovery for it anyway: it either commits or it rolls back, there's no in between situation.


                      Gooood question - which is what I'm trying to find out definitively. Our JMS MDB bean calls into our SLSB layer, which in turn calls out to the DB. I think the 2PC is coming into play when these JMS MDBs receive messages and process them. All of our SLSBs use the one <xa-datasource>, with the possibility of also using that other <no-tx-datasource>. That no-tx datasource should be moot as part of this discussion since it should never get enlisted but because I haven't seen proof either way, I'm erring on the side of "I have no idea what its doing". But the only place where I can see 2PC ever coming into play is our JMS bean (JBossMQ XA resource) calling our SLSBs (which then enlist the DB XA resource). But I sure would like to see proof of this :) I will see if I can look at the TM debug messages.

                      Well if the TM is doing its job then you shouldn't see much overhead at all when using a single resource and zero overhead when using no resources. So scoping work within a transaction in your case by default may be worth the trouble in the event things change that you didn't foresee.


                      This is what I hope and what I expect. Most of our txs are using just that one xa-datasource - so as I understand it, and as you just pointed out, 2PC overhead is virtually non-existent (at least not enough to worry about) for most of my transactions. This is what I want to prove. I want to see the performance of my app get affected very little, even though I switched from local-tx-datasource to xa-datasource, because, in reality, I'm very rarely enlisting more than one resource in a tx (or, at least, I think I am).

                      Another BTW ... I'm on vacation for the next 2 weeks so if you're really nice I could do the above modification for you if you want ;-)


                      What constitutes "really nice"? I would like something to help test/verify this stuff. Anything you can provide would be "greatly appreciated". That's really nice of me to say so ;)

                      Yes, I know 441 is triggered by the ats integration db recovery resource, but you can easily create a stand-alone version.


                      Not a problem. I've already got my own recovery resource implemented - in fact, I attached my fix for 441 to that JIRA issue for others to use, as they see fit (see https://jira.jboss.org/jira/browse/JBTM-441)

                      • 8. Re: find out how many resources are enlisted in tx
                        mazz Master

                        OK, for those interested, the URL to the admin guide where I found information on setting up targeted debug messages is here:

                        http://www.jboss.org/jbosstm/docs/4.2.3/manuals/html/core/AdministrationGuide.html

                        I have this set to enable facility codes FAC_ATOMIC_ACTION (0x1), FAC_ABSTRACT_REC (0x8), FAC_OBJECT_STORE (0x10) and FAC_CRASH_RECOVERY (0x800):

                        <property name="com.arjuna.common.util.logging.DebugLevel"
                         type="System" value="0xffffffff"/>
                        <property name="com.arjuna.common.util.logging.FacilityLevel"
                         type="System" value="0x00000819"/>
                        <property name="com.arjuna.common.util.logging.VisibilityLevel"
                         type="System" value="0xffffffff"/>


                        I see debug now, and messages I see alot of is:

                        DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.enlistResource ( org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@6e942d )
                        ...
                        DEBUG [arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for a0b0c92:acd:494fba89:25d


                        There's my record list I was looking for. Therefore, can I assume that if I always see "::insert(RecordList: empty)" that I am only ever enlisting a single resource in my transactions?

                        I will assume that if I see something like "::insert(RecordList: **something**)" that the **something** is a XA resource already enlisted and that I'm enlisting more than one resource in the transaction. Let me know if I'm on the right track - this all seems to make sense to me, but that sometimes happens when I'm sniffing glue (I should stop that).

                        I also see these:

                        DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::onePhaseCommit() for action-id a0b0c92:b59:494fbdea:81c
                        DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelOnePhaseCommit for
                        < 131075, 26, 24, 1-a0b0c92:b59:494fbdea:81ca0b0c92:b59:494fbdea:823


                        "onePhaseCommit" - can I also assume that this is saying, even though I am using an XA resource that the JBossTS was smart enough to say, "there is only one resource enlisted in the transaction, so I am not going to perform 2PC" ??

                        Next up to get some JMS messages flowing and see how these debug logs differ.

                        • 9. Re: find out how many resources are enlisted in tx
                          Mark Little Master

                          Hi Mazz. Only time for a quick update. I've scanned your questions and the answers are: yes, that message means a participant (could be 1PC or 2PC aware) has been enlisted, and yes onePhaseCommit means we've ignored the log.

                          However, and here's the reason for the update, I ran my test for 418 just before I had to dash out (Christmas shopping!) and it failed against a clean trunk, but passed against my usual build setup. This could be a problem at my end (bad config, wrong source etc.) so I need to double check later. But I'll definitely let you know: my aim is to point you at a simple test that should illustrate 418 and be modifiable for 441 as well. Can't promise to get to this tonight (my time), but I will get to it asap.


                          • 10. Re: find out how many resources are enlisted in tx
                            Mark Little Master

                            Oh and this is fun compared to Christmas shopping ;-)!

                            • 11. Re: find out how many resources are enlisted in tx
                              mazz Master

                              OK, I think I am finally able to read the JBossTM debug messages intelligently now (before I used to stare at them as if written in Latin :)

                              I'm documenting them here mainly so I can come back and refer to them myself but I think it might help others that want to trace tx's through the system.

                              These logs are occurring when I send my JMS message and my JMS consumer bean is processing it (which calls my SLSB method while doing so - which uses the <xa-datasource> to get to the DB). I can see more than one resource enlisted in the tx and 2PC happening based on the following series of events:

                              This shows the transaction beginning - my JMS bean is about to be invoked - notice the "action-id" ends with "b2c" - this is important as I believe this identifies the transaction because it appears in many of the messages later:

                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.jta.logging.logger] BaseTransaction.begin
                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::BasicAction()
                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::Begin() for action-id a0b0c92:10e4:494ff942:b2c
                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::actionInitialise() for action-id a0b0c92:10e4:494ff942:b2c
                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ActionHierarchy::ActionHierarchy(5)
                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ActionHierarchy::add(a0b0c92:10e4:494ff942:b2c, 1)
                              


                              Here you can see the thread getting associated with the transaction; I believe this "JBoss Pooled Thread" is part of the JMS infrastructure - it will be where my JMS bean invocation occurs:

                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action a0b0c92:10e4:494ff942:b2c adding Thread[WorkManager(2)-4,5,JBoss Pooled Threads]
                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action a0b0c92:10e4:494ff942:b2c adding Thread[WorkManager(2)-4,5,JBoss Pooled Threads] result = true
                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::create ( 120000 )
                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::insert ( BasicAction: a0b0c92:10e4:494ff942:b2c status: ActionStatus.RUNNING, 600 )
                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ReaperElement::ReaperElement ( BasicAction: a0b0c92:10e4:494ff942:b2c status: ActionStatus.RUNNING, 600 )
                              


                              Here's an important part! My XA resource is being enlisted in the transaction - I can't tell, but I think this JcaXAResourceWrapper is wrapping the JBossMQ XA resource:

                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.enlistResource ( org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@ec63cf )
                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (a0b0c92:10e4:494ff942:b2e, 1)
                              2008-12-22 15:34:22,546 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.XAResourceRecord ( < 131075, 27, 25, 1-a0b0c92:10e4:494ff942:b2ca0b0c92:10e4:494ff942:b2d ...>
                              2008-12-22 15:34:22,562 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: empty) : appending /StateManager/AbstractRecord/XAResourceRecord for a0b0c92:10e4:494ff942:b2e


                              This part I do not understand - why is it suspending the transaction, then quickly resuming it - it looks like it is disassociating some "TSThread" from the transaction during the suspension. Note after the resume, it is associating the tx with the "JBoss Pooled Thread" again (didn't it already associate this thread with the transaction already? from above - the messages are identical)
                              2008-12-22 15:34:22,562 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.suspend
                              2008-12-22 15:34:22,609 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_8] - BasicAction::removeChildThread () action a0b0c92:10e4:494ff942:b2c removing TSThread:15
                              2008-12-22 15:34:22,609 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_9] - BasicAction::removeChildThread () action a0b0c92:10e4:494ff942:b2c removing TSThread:15 result = true
                              2008-12-22 15:34:22,609 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImpleManager.resume
                              2008-12-22 15:34:22,609 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_6] - BasicAction::addChildThread () action a0b0c92:10e4:494ff942:b2c adding Thread[WorkManager(2)-4,5,JBoss Pooled Threads]
                              2008-12-22 15:34:22,609 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.BasicAction_7] - BasicAction::addChildThread () action a0b0c92:10e4:494ff942:b2c adding Thread[WorkManager(2)-4,5,JBoss Pooled Threads] result = true
                              


                              This is a debug message from my JMS code - it is logged in my onMessage() method, so at this point I know my JMS bean is being invoked and I'm in a transaction. Note that soon after this log message is emitted, I make a call to a SLSB method with a EJB3 @Requires annotation, so it remains in the same tx:
                              2008-12-22 15:34:22,609 DEBUG [org.rhq.enterprise.server.alert.engine.jms.AlertConditionConsumerBean] Received message: ActiveAlertConditionMessage[ value= 5.726432E7, AbstractAlertConditionMessage[ alertConditionId=500050, timestamp=1229978057000 ] ]
                              


                              Bingo! Here I am enlisting another resource in the transaction as expected - this must be my <xa-datasource> that my SLSB method wants to use. You can see the RecordList isn't empty here - I have one resource already enlisted in this tx - I'm adding a second one:

                              2008-12-22 15:34:22,609 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.enlistResource ( org.jboss.resource.connectionmanager.xa.JcaXAResourceWrapper@14e849c )
                              2008-12-22 15:34:22,609 DEBUG [com.arjuna.ats.jta.logging.logger] TransactionImple.getStatus
                              2008-12-22 15:34:22,609 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] AbstractRecord::AbstractRecord (a0b0c92:10e4:494ff942:b37, 1)
                              2008-12-22 15:34:22,609 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.XAResourceRecord ( < 131075, 27, 25, 1-a0b0c92:10e4:494ff942:b2ca0b0c92:10e4:494ff942:b36 ... > )
                              2008-12-22 15:34:22,609 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.arjuna.coordinator.RecordList_5] - RecordList::insert(RecordList: a0b0c92:10e4:494ff942:b2e) : appending /StateManager/AbstractRecord/XAResourceRecord for a0b0c92:10e4:494ff942:b37
                              


                              After a bunch of stuff happens, I then see my transaction end, and start its prepare phase (so I confirmed that this is 2PC!) - I can also see it getting the object store ready:

                              2008-12-22 15:34:23,062 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::End() for action-id a0b0c92:10e4:494ff942:b2c
                              2008-12-22 15:34:23,062 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::prepare () for action-id a0b0c92:10e4:494ff942:b2c
                              2008-12-22 15:34:23,062 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.ShadowingStore( 14 )
                              2008-12-22 15:34:23,062 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowNoFileLockStore.ShadowNoFileLockStore( 14 )
                              2008-12-22 15:34:23,062 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.HashedStore( 14 )
                              2008-12-22 15:34:23,062 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.HashedActionStore()
                              2008-12-22 15:34:23,062 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.setupStore()
                              2008-12-22 15:34:23,062 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.createHierarchy(C:\mazz\source\rhq\trunk\dev-container\jbossas\server\default\data/tx-object-store\HashedActionStore\defaultStore\)
                              2008-12-22 15:34:23,062 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelPrepare for < 131075, 27, 25, 1-a0b0c92:10e4:494ff942:b2ca0b0c92:10e4:494ff942:b2d ...>
                              2008-12-22 15:34:23,078 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelPrepare for < 131075, 27, 25, 1-a0b0c92:10e4:494ff942:b2ca0b0c92:10e4:494ff942:b36 ...>


                              Here is the transaction log getting written to the object store on the file system - now I know what log messages to look for when I want to find out when a tx log is getting written to the object store :)

                              2008-12-22 15:34:23,125 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.write_committed(a0b0c92:10e4:494ff942:b2c, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
                              2008-12-22 15:34:23,125 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.write_state(a0b0c92:10e4:494ff942:b2c, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
                              2008-12-22 15:34:23,125 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(a0b0c92:10e4:494ff942:b2c, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
                              2008-12-22 15:34:23,125 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.openAndLock(C:\mazz\source\rhq\trunk\dev-container\jbossas\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#142#\a0b0c92_10e4_494ff942_b2c, FileLock.F_WRLCK, true)
                              2008-12-22 15:34:23,125 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.createHierarchy(C:\mazz\source\rhq\trunk\dev-container\jbossas\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#142#\a0b0c92_10e4_494ff942_b2c)
                              2008-12-22 15:34:23,125 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.closeAndUnlock(C:\mazz\source\rhq\trunk\dev-container\jbossas\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#142#\a0b0c92_10e4_494ff942_b2c, null, java.io.FileOutputStream@4aecf9)
                              


                              Next up - 2PC commit phase!

                              2008-12-22 15:34:23,125 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::phase2Commit() for action-id a0b0c92:10e4:494ff942:b2c
                              2008-12-22 15:34:23,125 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@d478e7)
                              2008-12-22 15:34:23,125 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelCommit for < 131075, 27, 25, 1-a0b0c92:10e4:494ff942:b2ca0b0c92:10e4:494ff942:b2d
                              2008-12-22 15:34:23,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::doCommit (com.arjuna.ats.internal.jta.resources.arjunacore.XAResourceRecord@cbc94e)
                              2008-12-22 15:34:23,203 DEBUG [com.arjuna.ats.jta.logging.logger] XAResourceRecord.topLevelCommit for < 131075, 27, 25, 1-a0b0c92:10e4:494ff942:b2ca0b0c92:10e4:494ff942:b36


                              And here I can see it removing the tx log from the object store, now that we successfully committed, I assume this would NOT happen if the transaction actually failed in the previous prepare or commit phase:

                              2008-12-22 15:34:23,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] BasicAction::updateState() for action-id a0b0c92:10e4:494ff942:b2c
                              2008-12-22 15:34:23,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] FileSystemStore.remove_committed(a0b0c92:10e4:494ff942:b2c, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction)
                              2008-12-22 15:34:23,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.remove_state(a0b0c92:10e4:494ff942:b2c, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
                              2008-12-22 15:34:23,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(a0b0c92:10e4:494ff942:b2c, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_SHADOW)
                              2008-12-22 15:34:23,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(a0b0c92:10e4:494ff942:b2c, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
                              2008-12-22 15:34:23,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLoggerI18N] [com.arjuna.ats.internal.arjuna.objectstore.ShadowingStore_22] - ShadowingStore.currentState(a0b0c92:10e4:494ff942:b2c, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction) - returning ObjectStore.OS_COMMITTED
                              2008-12-22 15:34:23,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] HashedStore.genPathName(a0b0c92:10e4:494ff942:b2c, /StateManager/BasicAction/TwoPhaseCoordinator/AtomicAction, ObjectStore.OS_ORIGINAL)
                              2008-12-22 15:34:23,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.openAndLock(C:\mazz\source\rhq\trunk\dev-container\jbossas\server\default\data/tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#142#\a0b0c92_10e4_494ff942_b2c, FileLock.F_WRLCK, false)
                              2008-12-22 15:34:23,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] ShadowingStore.closeAndUnlock(C:\mazz\source\rhq\trunk\dev-container\jbossas\server\default\data\tx-object-store\HashedActionStore\defaultStore\StateManager\BasicAction\TwoPhaseCoordinator\AtomicAction\#142#\a0b0c92_10e4_494ff942_b2c, null, null)


                              And finally, looks like the reaper is removing this transaction now that it has been committed and the tx log has been cleaned out from the object store:

                              2008-12-22 15:34:23,203 DEBUG [com.arjuna.ats.arjuna.logging.arjLogger] TransactionReaper::remove ( BasicAction: a0b0c92:10e4:494ff942:b2c status: ActionStatus.COMMITTED )


                              These logs are very informative, once you know how to pin-point-enable the debug messages using the FAC_xxx facility codes. I'll be using these alot more in the future ; )

                              • 12. Re: find out how many resources are enlisted in tx
                                Mark Little Master

                                Glad you found them useful :-)

                                The suspend/resume is because we have to remove any existing thread-to-transaction association before changing it. If there's no transaction associated then this is simply a null-op.

                                BTW, want to add your adventures in transaction logging land to our wiki :-) ?

                                • 13. Re: find out how many resources are enlisted in tx
                                  Mark Little Master

                                  I've got some good news. It was a config problem at my side and the test runs with both my workspace code as well as a freshly checked out trunk. I'm running it a few more times just to be sure (minimum time to prune the log is an hour) but I'll try and post something either late tonight or early tomorrow my time.

                                  • 14. Re: find out how many resources are enlisted in tx
                                    mazz Master

                                    OK, now this is not so daunting - I am finally understanding this stuff :)

                                    Once I got these targeted log messages to come out and once I understood the basic concepts behind the TM and what these messages are telling me, I was able to refactor some of my code and actually see the TM behave as predicted.

                                    I found the places where I was enlisting multiple resources (2 to be exact) in a single tx. As expected, it was in the JMS code. Actually, in two places. One was in the consumer SLSB bean (the bean that gets the JMS messages) and the other was in the "producer" SLSB bean - the guy that actually sends the JMS messages (i.e. the one putting the messages on the JMS queue). In both places, I made some changes to ensure that I am now using the EJB3 annotation for @REQUIRES_NEW - thus ensuring that the JMS XA resource was NOT enlisted in my SLSB methods' transactions. This allows my SLSB methods to enlist just my single DB XA resource in the txs thus avoiding 2PC.

                                    Before I made the change, I saw phase2Commit() being called by the TM and I saw the object store get tx logs written to it at the time I was performing the JMS work. Once I made the change to use REQUIRES_NEW, I immediately saw those two things disappear from the logs and in their place, just a bunch of calls to onePhaseCommit(). Therefore, I've proven to myself that I was able to eliminate the usage of 2PC in my app (after examining the code, I did confirm that we really do not need it here - suspending a tx and entering a new tx is OK for our use-cases here).

                                    1 2 Previous Next