TXMBeanStats.btm Creates MBean But No Updates

[nwhitehead]

Hello;

I have this issue in Byteman 1.5.1 and the current 1.6.1 from Git trunk.

The script installs with no issue and I see the MBean created, but the values are never updated, and I know there's transactions going on, since when I look at the Arjuna Performance Statistics MBean in  jmx-console, the counters are humming.

The byteman MBean does not show any activity at all.

The initialization is:

set BYTEMAN_HOME=c:\libs\java\byteman\1.6.1

........

set JAVA_OPTS=%JAVA_OPTS% -javaagent:%BYTEMAN_HOME%\lib\byteman.jar=listener:true,port:9091,address:0.0.0.0,script:%BYTEMAN_HOME%\sample\scripts/TXMBeanStats.btm,sys:%BYTEMAN_HOME%\sample\lib\byteman-sample.jar

Initially, I ran the script unmodified, but on reviewing it, it seemed the PeriodicHelper was missing, so I added in:

HELPER org.jboss.byteman.sample.helper.PeriodicHelper

RULE set period

CLASS PeriodicHelper

METHOD getPeriod()

IF TRUE

DO RETURN 10 * 1000

ENDRULE

Still no activity though. I was able to successfully unload the rule set using bmsubmit but when I reloaded the script, even the MBean won't show up.

I must be missing something. Any direction appreciated !

//Nicholas

======== Update

I turned on debug and I see activity related to the rule set, but the MBean data is still inert.

16:28:45,197 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

16:28:45,203 INFO  main [STDOUT] org.jboss.byteman.agent.Transformer : possible trigger for rule return key info in class org.jboss.byteman.sample.helper.JMXHelper

16:28:45,204 INFO  main [STDOUT] RuleTriggerMethodAdapter.injectTriggerPoint : inserting trigger into org.jboss.byteman.sample.hel

per.JMXHelper.keyInfo() org.jboss.byteman.sample.helper.KeyInfo for rule return key info

16:28:45,209 INFO  main [STDOUT] org.jboss.byteman.agent.Transformer : inserted trigger for return key info in class org.jboss.byt

eman.sample.helper.JMXHelper

16:28:45,219 INFO  main [STDOUT] HelperManager.install for helper classorg.jboss.byteman.sample.helper.JMXHelper

16:28:45,220 INFO  main [STDOUT] calling activated() for helper classorg.jboss.byteman.sample.helper.JMXHelper

16:28:45,221 INFO  main [STDOUT] calling installed(count setRollbackOnly request) for helper classorg.jboss.byteman.sample.helper.

JMXHelper

16:28:45,221 INFO  main [STDOUT] Installed rule using default helper : count setRollbackOnly request

16:28:45,221 INFO  main [STDOUT] count setRollbackOnly request execute()

16:28:45,221 INFO  Periodic Helper Thread [STDOUT] Rule.execute called for return key info_3

16:28:45,226 INFO  Periodic Helper Thread [STDOUT] HelperManager.install for helper classorg.jboss.byteman.sample.helper.JMXHelper

16:28:45,226 INFO  Periodic Helper Thread [STDOUT] calling installed(return key info) for helper classorg.jboss.byteman.sample.hel

per.JMXHelper

16:28:45,226 INFO  Periodic Helper Thread [STDOUT] Installed rule using default helper : return key info

16:28:45,228 INFO  Periodic Helper Thread [STDOUT] return key info execute()

16:28:45,228 INFO  Periodic Helper Thread [STDOUT] caught ReturnException

16:28:45,229 INFO  Periodic Helper Thread [STDOUT] Rule.execute called for return key info_3

16:28:45,229 INFO  Periodic Helper Thread [STDOUT] return key info execute()

16:28:45,229 INFO  Periodic Helper Thread [STDOUT] caught ReturnException

16:28:45,254 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

16:28:45,254 INFO  main [STDOUT] count setRollbackOnly request execute()

16:28:45,258 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

16:28:45,259 INFO  main [STDOUT] count setRollbackOnly request execute()

16:28:45,262 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

16:28:45,262 INFO  main [STDOUT] count setRollbackOnly request execute()

16:28:45,265 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

16:28:45,266 INFO  main [STDOUT] count setRollbackOnly request execute()

16:28:45,269 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

16:28:45,269 INFO  main [STDOUT] count setRollbackOnly request execute()

16:28:45,273 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

[adinn]

Hi Nicholas,

Thanks very much for reporting your experience with this example.

The initialization is:
set BYTEMAN_HOME=c:\libs\java\byteman\1.6.1
........
set JAVA_OPTS=%JAVA_OPTS% -javaagent:%BYTEMAN_HOME%\lib\byteman.jar=listener:true,port:9091,address:0.0.0.0,script:%BYTEMAN_HOME%\sample\scripts/TXMBeanStats.btm,sys:%BYTEMAN_HOME%\sample\lib\byteman-sample.jar 

Yes, that looks perfectly correct. You don't actually need to specify the port and address but they do no harm.

Initially, I ran the script unmodified, but on reviewing it, it seemed the PeriodicHelper was missing, so I added in:

HELPER org.jboss.byteman.sample.helper.PeriodicHelper

RULE set period

CLASS PeriodicHelper

METHOD getPeriod()

IF TRUE

DO RETURN 10 * 1000

ENDRULE

In the release version of the script the helper is set at line 110 before any of the rules are declared.

HELPER org.jboss.byteman.sample.helper.JMXHelper

This line ensures that all rules which do not embed a HELPER clause will use JMXHelper. By inserting you initial line you have changed the helper to class PeriodicHelper. This differs from JMXHelper in two important respects.

• PeriodicHelper does not install an MBean whereas JMXHelper does.
• The background thread created by PeriodicHelper regularly calls empty method PeriodicHelper.periodicTrigger() to update its stats and the script is expected to inject code into this method. By contrast the background thread created by JMXHelper regularly calls JMXHelper.periodicUpdate() which you shoudl not need to inject code into. It samples the stats identified by the returned jey list and displays them in the MXBean.

So, by redefining the helper you have disabled the MXBean creation and also ensured that nothing happens when the background thread runs..

Also, your set period rule is assigning the period to 10 seconds. This is the default value used by both PeriodicHelper and JMXHelper. So this rule wil make no difference to the behavour of the injected code.

Still no activity though. I was able to successfully unload the rule set using bmsubmit but when I reloaded the script, even the MBean won't show up.

This is most likely because you have reset the helper.

======== Update

I turned on debug and I see activity related to the rule set, but the MBean data is still inert.

16:28:45,197 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

16:28:45,203 INFO  main [STDOUT] org.jboss.byteman.agent.Transformer : possible trigger for rule return key info in class org.jboss.byteman.sample.helper.JMXHelper

16:28:45,204 INFO  main [STDOUT] RuleTriggerMethodAdapter.injectTriggerPoint : inserting trigger into org.jboss.byteman.sample.hel

per.JMXHelper.keyInfo() org.jboss.byteman.sample.helper.KeyInfo for rule return key info

16:28:45,209 INFO  main [STDOUT] org.jboss.byteman.agent.Transformer : inserted trigger for return key info in class org.jboss.byt

eman.sample.helper.JMXHelper

16:28:45,219 INFO  main [STDOUT] HelperManager.install for helper classorg.jboss.byteman.sample.helper.JMXHelper

16:28:45,220 INFO  main [STDOUT] calling activated() for helper classorg.jboss.byteman.sample.helper.JMXHelper

16:28:45,221 INFO  main [STDOUT] calling installed(count setRollbackOnly request) for helper classorg.jboss.byteman.sample.helper.

JMXHelper

16:28:45,221 INFO  main [STDOUT] Installed rule using default helper : count setRollbackOnly request

16:28:45,221 INFO  main [STDOUT] count setRollbackOnly request execute()

16:28:45,221 INFO  Periodic Helper Thread [STDOUT] Rule.execute called for return key info_3

16:28:45,226 INFO  Periodic Helper Thread [STDOUT] HelperManager.install for helper classorg.jboss.byteman.sample.helper.JMXHelper

16:28:45,226 INFO  Periodic Helper Thread [STDOUT] calling installed(return key info) for helper classorg.jboss.byteman.sample.hel

per.JMXHelper

16:28:45,226 INFO  Periodic Helper Thread [STDOUT] Installed rule using default helper : return key info

16:28:45,228 INFO  Periodic Helper Thread [STDOUT] return key info execute()

16:28:45,228 INFO  Periodic Helper Thread [STDOUT] caught ReturnException

16:28:45,229 INFO  Periodic Helper Thread [STDOUT] Rule.execute called for return key info_3

16:28:45,229 INFO  Periodic Helper Thread [STDOUT] return key info execute()

16:28:45,229 INFO  Periodic Helper Thread [STDOUT] caught ReturnException

16:28:45,254 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

16:28:45,254 INFO  main [STDOUT] count setRollbackOnly request execute()

16:28:45,258 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

16:28:45,259 INFO  main [STDOUT] count setRollbackOnly request execute()

16:28:45,262 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

16:28:45,262 INFO  main [STDOUT] count setRollbackOnly request execute()

16:28:45,265 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

16:28:45,266 INFO  main [STDOUT] count setRollbackOnly request execute()

16:28:45,269 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

16:28:45,269 INFO  main [STDOUT] count setRollbackOnly request execute()

16:28:45,273 INFO  main [STDOUT] Rule.execute called for count setRollbackOnly request_0

I assume this is trace when you reloaded the original script from the command line? It certainly shows rules being fired using JMXHelper as the helper class. It also shows triggering of the setRollbackOnly rule and triggering of the rules which the background thread started by JMXHelper will hit when it starts running. So, rule injection, MBean creation and stats gathering all appear to be working. Which means the prime suspect is the detaisl of the ruel sin the script itself.

Looking at the trace I notice that one rule which definitely ought to be counting events is the rollback rule. Here are the relevant sections of the script:

RULE return key info
CLASS JMXHelper
METHOD keyInfo()
BIND keyInfo : KeyInfo = new KeyInfo("JBossTS Statistics in a Dynamic MBean")
IF TRUE
DO keyInfo.addKey("TX begin", KeyInfo.KEY_TYPE_CUMULATIVE, "TX begin total");
   . . .
   keyInfo.addKey("TX setRollbackOnly", KeyInfo.KEY_TYPE_CUMULATIVE, "TX setRollbackOnly total");
   . . .
   keyInfo.addKey("TX setRollbackOnly", KeyInfo.KEY_TYPE_RATE, "TX setRollbackOnly request/second");
   . . .
   keyInfo.addKey("TX setRollbackOnly", KeyInfo.KEY_TYPE_MEAN, "TX setRollbackOnly average");
   . . .
   RETURN keyInfo
ENDRULE

   . . .

RULE count setRollbackOnly request
INTERFACE javax.transaction.Transaction
METHOD setRollbackOnly()
IF TRUE
DO incrementCounter("TX setRollbackOnly request")
ENDRULE

It's fairly obvious once you look. The coiunter key inserted into the keylist returned to the background thread and the counter key passed in the call to incrementCounter need to be the same otherwise the background thread will sample the wrong counter. The script is consistently using the wrong keys -- clearly a partial edit on my part. If you globally substitute incrementCounter("XXX request") with incrementCounter("XXX") it ought to start working.

n.b. another error: the key "TX rollback" is added twice at each occurence in rule "return key info".

I will raise a JIRA for this and fix it in the next release. Thanks very much for reporting the problem.

regards,

Andrew Dinn

[adinn]

Here is the JIRA:

  https://issues.jboss.org/browse/BYTEMAN-169

[adinn]

Hmm, this is interesting. There is a further problem with this script and it's not straightforward to fix. I'll explain at length here then provide a patched script.

The first counting rule in the script is this

# this rule is triggered when a call is made to Transaction.begin

RULE count begin request
INTERFACE javax.transaction.Transaction
METHOD begin()
IF TRUE
DO incrementCounter("TX begin")
ENDRULE

Spotted the problem yet? Yes, Transaction does not actually have a begin() method. UserTransaction, yes. TransactionManager, yes. But not Transaction.

So, why are the rules attached to Transaction and not UserTransaction anyway? Well, its actually a complex story but, in essence, it's because the real action in any implementation happens in a class like our TransactionImple which implements javax.transaction.Transaction. So, any commit, whether it goes through UserTransaction.commit() or TransactionManager.commit() will execute some implementation of Transaction.commit(). Same for all the other methods . . . except for begin()!

What's the deal with begin()? It comes down to the fact that UserTransaction is actually a bit of a lie. You can see this when you look at the details of how we implement it in JBoss Transactions. It also means that this rule set cannto be fixed without installing JBoss specific rules. Here's the details.

In the Arjuna code interface UserTransaction is implemented by a class called UserTransactionImple. Similarly, TransactionManager is implemented by a class called TransactionManagerimple. Actually, there are two implementations, one for JTA and one for JTS but let's just assume we are using the JTA versions. So, both these implementations need to provide methods begin, commit, rollback etc. TransactionManager also needs to provide methods suspend, resume and getTransaction which allow the curretn Transaction (not UserTransaction) to be manipulated.

In the JBoss implementation both classes inherit from a common class BaseTransaction which implements the common methods, including begin. So, if we want ot count transaction begin calls we want to instrument calls to BaseTransaction.begin(). But we cannot do this with a rule attached to UserTransaction nor with a rule attached to TransactionManager. Neither of these interfaces is implemented by BaseTransaction. Yes, that's weird but its quite legitimate in Java. The two subclasses which each implement one of these two interfaces can both inherit the same implementation from a class which knows nothing about the interfaces.

Imagine we redefined the rule so it was attached to UserTransaction. When the rule is loaded Byteman identifies that this interface is implemented by UserTransactionImple. So, it checks whether the class implements method begin() and finds that no, it doesn't. So, nothing to inject. Byteman cannot inject code into the inherited method. Why? Well, firstly, that would side effect instances of TransactionManagerImple which has nothing to do with UserTransaction, so it does something the rel does not request. Also, imagine that the injected code referred to $0, say calling a method of UserTransaction which is not also implemented by TransactionManager. If we restrict injection to implementors of UserTransaction (or their sublcasses) then we will not get a type error. If we injected into the begin() method of BaseTransaction the injected code would be assuming that a BaseTransaction could be used as a UserTransaction and that woudl be invalid under a call to TransactionManager.begin().

So why did I say UserTransaction a lie? Well, look at the fact that method commit is actally the same for both UserTransaction and TransactionManager. In the first case an instance method of UserTransaction is used to commit the *current* transaction. In the second case an instance method of TransactionManager is used to commit the *current* transaction. In both cases this is the same code?

You have to ask yourself why doesn't TransactionManager.commit() take a UserTransaction as an argument? At first glance it looks like it is just a convenience method which indirects to the UserTransaction implementation, a shorthand for TransactionManager,getTransaction().commit().  But surely it cannot be defined like that because then it could not inherit the same implementation as UserTransaction  Well, when you look at getTransaction() you see why. getTransaction() returns a Transaction, not a UserTransaction. Yes, that shorthand is correct. What is opaque is that UserTransaction instance whose commit method you call is really nothing to do with the *current* transaction. It also indirects to a Transaction instance.

Both the TransactionManager and UserTransaction objects which field these calls are pseduo-instances in that their identity is irrelevant. In fact, we only ever create a singleton instance for each of these classes. You have to obtain a handle on that singleton instance in ordert to invoke their APIs but they both operate indirectly on the Transaction instance associated with the current thread. So, when you call commit they both locate the current transaction in a ThreadLocal and then tell it to commit. Ditto for almost all the shared methods.

Now, what about begin(). Well, in this case they also both do the same thing, i.e. create a Transaction (actuially TransactionImple) instance and associate it with the calling thread. But they don't do so by calling an implementation of Transaction.begin(). There is no instance around to pass the message on to. What they actually do is create a new instance of an implementation-dependent class whcih implements Transaction. That's why there is no Transaction.begin() method for Byteman to intercept.

Ok, so can we nto still couint the create operations in an implementation independent way? No. In order to fix this script the counitng rule will need to be injected into BaseTransaction.begin() or to TransactionImple.<init>() (the constructor method) to esnure that we increment the counter every time we get a new Transaction implemntation instance. If you want to use the script with some other TM then you will have to redefine it as appropriate to that TM.

A patch for this should arrive soon.

regards,

Andrew Dinn

[nwhitehead]

Hello Andrew;

Thank you for your detailed response. I printed a cup of coffee and went of to drink your post.

I removed the PeriodicHelper declaration, removed the errant request text from increment operations and just to get something up and working, I replaced all instances of

INTERFACE javax.transaction.Transaction

with

CLASS com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction

and now I am seeing some action.

I suggest a means of declaring non-obvious relationships in terms of aliases. For example:

RULE Transaction Aliases

INTERFACE java.transaction.Transaction

ALIAS com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction

ALIAS  <some other class>

ALIAS  <some other class>.<narrowing method>

ENDRULE

Another area that might be helpful is the ability to attach methods in classes that are annotated with a specific annotation, which in turn could be declared in the form of an alias.

Thanks again for your help.

//Nicholas   

[adinn]

Hi Nicholas,

Nicholas Whitehead wrote:

Thank you for your detailed response. I printed a cup of coffee and went of to drink your post.

I hope the potion was effective.

Nicholas Whitehead wrote:

I replaced all instances of

INTERFACE javax.transaction.Transaction

with

CLASS com.arjuna.ats.internal.jta.transaction.arjunacore.BaseTransaction

and now I am seeing some action.

This is indeed one perfectly valid option. However, in the patch I just submitted to the Byteman GIT repo I chose instead to leave the bulk of the rules attached to javax.transaction Transaction and to replace the begin rule with a pair of rules defined as follows:

# this rule is triggered when a JBoss JTA Transaction instance is created

RULE count begin request
CLASS com.arjuna.ats.internal.jta.transaction.arjunacore.TransactionImple
METHOD <init>
IF TRUE
DO incrementCounter("TX begin")
ENDRULE

# this rule is triggered when a call is made to Transaction.<init>

RULE count begin request
CLASS com.arjuna.ats.internal.jta.transaction.jts.TransactionImple
METHOD <init>
IF TRUE
DO incrementCounter("TX begin")
ENDRULE

Why? Well, the methods you instrumented get called whenever the APP code operates on a transaction via UserTransaction or TransactionManager. The methods I instrumented are called whenever either the APP code or the container code operates on a transaction. Of course which stats you want to be displayed depends on your interest. Hope this improves the flavour of your brew.

regards,

Andrew Dinn