4 Replies Latest reply on Mar 9, 2018 11:28 AM by Andrew Dinn

    Rules must be unloaded and reloaded to work

    Hermann Huebler Newbie

      Hey,

      I'm following the byteman blog at Byteman Blog: Collecting and Displaying Runtime Statistics With Byteman with some modifications to collect some thread related statistics. I'm using byteman 4.0.1 with Wildfly 11 running Java 9.0.1 (Java HotSpot(TM) 64-Bit Server VM (build 9.0.1+11, mixed mode)).

       

      The rule which defines the attributes for the dynamic MBean is the following:

      --- snip ---

      # ensure all rules employ the JMX helper class

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

       

      # this rule is triggered when the periodic helper thread starts

      # it returns a KeyInfo object identifying the stats counters

      # updated by rules in this rule set

      RULE return key info

      CLASS JMXHelper

      METHOD keyInfo()

      BIND keys : KeyInfo = new org.jboss.byteman.sample.helper.KeyInfo("JVM Statistics in a Dynamic MBean")

      IF TRUE

      DO debug("HHUE: Setting MBean keys ...");

          keys.addKey("active threads", KeyInfo.KEY_TYPE_CUMULATIVE, "Currently running threads");

          keys.addKey("pools size", KeyInfo.KEY_TYPE_CUMULATIVE, "Size of thread pool");

          keys.addKey("queue size", KeyInfo.KEY_TYPE_CUMULATIVE, "Size of thread pool queue");

          debug("HHUE: Length of keys is: " + keys.getKeyNames());

          RETURN keys

      ENDRULE

      --- snip ---

      Here I'm facing the problem that after the first load of the rules file the keyInfo() method returns "No counters defined". However if I unload the rule file using bmsubmit.sh and reload the rule file using bmsubmit.sh I get all the attributes defined in the rule file shown in the dynamic MBean. This behavior is consistent.

       

      Thanks a lot in advance for any advise on what's wrong here - Hermann

        • 1. Re: Rules must be unloaded and reloaded to work
          Andrew Dinn Master

          Hi Herman,

           

          Thanks for posting this question.

          hhuebler  wrote:

          <snip>

          Here I'm facing the problem that after the first load of the rules file the keyInfo() method returns "No counters defined". However if I unload the rule file using bmsubmit.sh and reload the rule file using bmsubmit.sh I get all the attributes defined in the rule file shown in the dynamic MBean. This behavior is consistent.

          Hmm, that's interesting. I have not tried running this example on jdk9 or using the latest 4.0.1 release. I will give run through the steps in the blog post to see if I can reproduce the same problem and, if so, work out why the rule is not getting injected into the JMXHelper method first time round.

           

          I have a suspicion that this might relate to changes I made in the 4.0.X releases to fix some problems in calling of rule life-cycle methods (Helper methods activated, deactivated, installed and deinstalled). If the JMXHelper activated method is not getting called after this change or is getting called at a different point during the rule lifecycle then that may well explain why you are not seeing the 'return key info' rule being triggered.

           

          Meanwhile, could you try setting system property -Dorg.jboss.byteman.verbose when you install the Byteman agent (you can pass this on the command line with -javaagent or pass it as an option to bminstall). Amongst other things, this will trace calls to lifecycle methods, which may help to clarify the source of the problem. If you see anything interesting (like a failure to call the activated method of JMXHelper) let me know.

           

          regards,

           

           

          Andrew Dinn

          • 2. Re: Rules must be unloaded and reloaded to work
            Hermann Huebler Newbie

            Hello Andrew,

            I've recreated the scenario using -Dorg.jboss.byteman.verbose. At 12:09 I did the first load, at 12:10 I did the unload and at 12:11 I diud the second load of the rules. For some reasons the "return key info" rule is not loaded at the first load as you can see blow. From the trace I can't see any reason for that. Please find the lines below from the server.log:

             

            --- snip ---

            2018-03-09 12:09:16,855 INFO  [stdout] (ServerService Thread Pool -- 1) Default helper activated

            2018-03-09 12:09:16,858 INFO  [stdout] (ServerService Thread Pool -- 1) Installed rule using default helper : Count Active Threads2

            2018-03-09 12:09:16,860 INFO  [stdout] (ServerService Thread Pool -- 1) Installed rule using default helper : Count Active Threads2

            2018-03-09 12:09:16,862 INFO  [stdout] (ServerService Thread Pool -- 1) Count Active Threads2 execute()

            2018-03-09 12:09:18,284 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:09:23,298 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:09:26,865 INFO  [stdout] (ServerService Thread Pool -- 72) Count Active Threads2 execute()

            2018-03-09 12:09:28,311 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:09:33,321 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:09:36,866 INFO  [stdout] (ServerService Thread Pool -- 72) Count Active Threads2 execute()

            2018-03-09 12:09:38,334 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:09:41,033 INFO  [stdout] (expiration-thread--p4-t1) Count Active Threads2 execute()

            2018-03-09 12:09:41,036 INFO  [stdout] (expiration-thread--p3-t1) Count Active Threads2 execute()

            2018-03-09 12:09:41,038 INFO  [stdout] (expiration-thread--p4-t1) Count Active Threads2 execute()

            2018-03-09 12:09:43,339 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:09:46,867 INFO   [stdout] (ServerService Thread Pool -- 72) Count Active Threads2 execute()

            2018-03-09 12:09:48,347 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:09:53,354 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:09:56,869 INFO  [stdout] (ServerService Thread Pool -- 72) Count Active Threads2 execute()

            2018-03-09 12:09:58,361 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:10:03,368 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:10:05,785 INFO  [stdout] (Thread-0) Uninstalled rule using default helper : Count Active Threads2

            2018-03-09 12:10:05,787 INFO  [stdout] (Thread-0) Uninstalled rule using default helper : Count Active Threads2

            2018-03-09 12:10:05,788 INFO  [stdout] (Thread-0) Default helper deactivated

            2018-03-09 12:11:43,515 INFO  [stdout] (DeploymentScanner-threads - 1) Default helper activated

            2018-03-09 12:11:43,515 INFO  [stdout] (DeploymentScanner-threads - 1) Installed rule using default helper : Count Active Threads2

            2018-03-09 12:11:43,516 INFO  [stdout] (DeploymentScanner-threads - 1) Installed rule using default helper : Count Active Threads2

            2018-03-09 12:11:43,517 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:11:43,517 INFO  [stdout] (Periodic Helper Thread) Installed rule using default helper : set period

            2018-03-09 12:11:43,517 INFO  [stdout] (Periodic Helper Thread) Installed rule using default helper : set period

            2018-03-09 12:11:43,518 INFO  [stdout] (Periodic Helper Thread) set period execute()

            2018-03-09 12:11:43,518 INFO  [stdout] (Periodic Helper Thread) caught ReturnException

            2018-03-09 12:11:43,520 INFO  [stdout] (Periodic Helper Thread) Installed rule using default helper : return key info

            2018-03-09 12:11:43,520 INFO  [stdout] (Periodic Helper Thread) Installed rule using default helper : return key info

            2018-03-09 12:11:43,520 INFO  [stdout] (Periodic Helper Thread) return key info execute()

            2018-03-09 12:11:43,520 INFO  [stdout] (Periodic Helper Thread) caught ReturnException

            2018-03-09 12:11:43,521 INFO  [stdout] (Periodic Helper Thread) return key info execute()

            2018-03-09 12:11:43,521 INFO  [stdout] (Periodic Helper Thread) caught ReturnException

            2018-03-09 12:11:46,873 INFO  [stdout] (ServerService Thread Pool -- 33) Count Active Threads2 execute()

            2018-03-09 12:11:48,525 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:11:53,532 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:11:56,874 INFO  [stdout] (ServerService Thread Pool -- 33) Count Active Threads2 execute()

            2018-03-09 12:11:58,539 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:12:03,544 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:12:06,875 INFO  [stdout] (ServerService Thread Pool -- 33) Count Active Threads2 execute()

            2018-03-09 12:12:08,547 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:12:13,553 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            2018-03-09 12:12:16,876 INFO  [stdout] (ServerService Thread Pool -- 33) Count Active Threads2 execute()

            2018-03-09 12:12:18,559 INFO  [stdout] (DeploymentScanner-threads - 1) Count Active Threads2 execute()

            --- snip ---

            Hope that helps . thanks a lot in advance .. Hermann

            • 3. Re: Rules must be unloaded and reloaded to work
              Andrew Dinn Master

              Hi Hermann,

               

              Yes, I have just seen the same thing myself. I'm currently puzzled as to why the 'return key info' rule doesn't get executed first time round but does second time round. Anyway, I am debugging it now and will let you know as soon as I find out what is going on.

               

              n.b. this is a very nice catch, so many thanks for reporting it:-)

               

              regards,

               

               

              Andrew Dinn

              • 4. Re: Rules must be unloaded and reloaded to work
                Andrew Dinn Master

                Hi Hermann,

                 

                I have found out what the problem is, or rather the major problem which relates to the way that helper classes get loaded plus also a smaller problem -- a small error in rule script JVMBeanStats.btm. I have a fix for both and will push out an update in the next week or so. There is also a workaround which I will explain in a minute but that will require you tweaking class JMXHelper to provide your own version of the class.

                 

                The main problem you are seeing is happening because the rule which side-effects the keyInfo() call is being injected into the rule's helper class. This used to work fine in the past because a helper class used to be loaded the first time any rule using it was executed. However, some releases back changes were made to accommodate the JBoss Modules plugin so that the helper gets loaded when its associated rule is being injected. That results in the rules not being injected.

                 

                Just to explain roughly how it fails, consider what happens when you load the rule targeting method keyInfo() and Byteman tries to inject it into JMXHelper. At the point where you load the script class JMXHelper is not yet loaded into the JVM. So, the keyinfo rule is stored in Byteman's ScriptRespository awaiting a later load. The same applies for all the other rules which monitor JVM events. When one of the other rules gets triggered -- say for class Thread -- the Byteman Transformer is asked to modify the bytecode for class Thread. During this transform operation it checks the rule definition and loads the helper class JMXHelper. Now, the JVM is very strict about loading classes while in the middle of bytecode transformation. It will not recursively re-enter the transformer code. So, class JMXHelper never gets presented to the Byteman Transformer and the rules which target methods of JMXHelper fail to inject.

                 

                By contrast, when you unload the script and reload it class JMXHelper is already in the runtime. So, all the rules get injected at load time as expected.

                 

                The necessary fix is to delay loading of the helper class to execute time again. This should not actually cause a problem for the JBoss Modules plugin. The JIRA for this is BYTEMAN-357 .

                 

                The small related problem is the use of '\' in the JVMBeanStats.btm script. A few releases ago I realized that I had messed up the syntax for character escapes in String literals. You used to be able to use '\n', '\t' etc for special characters but any other use of '\' was just treated as a literal, ignoring the following character. I changed that so you have to write '\\' but forgot to update JVMBeanStats.btm. So, the two occurrences of '\.' in the stack backtrace wildcards need to be changed to '\\.' The JIRA for this is BYTEMAN-358.

                 

                Keep an eye out for release 4.0.2 which should permanently fix this problem.

                 

                Meanwhile, if you want a workaround I suggest you do the following:

                 

                Change the rules which inject into JMXHelper to inject into an inner class JMXHelperAux which we will define in a second:

                 

                RULE return key info
                CLASS JMXHelper$JMXHelperAux
                METHOD keyInfo()
                BIND keyInfo : KeyInfo = new KeyInfo("JVM Statistics in a Dynamic MBean")
                IF TRUE
                DO keyInfo.addKey("thread creates", KeyInfo.KEY_TYPE_CUMULATIVE, "Thread() total calls");
                   . . .

                 

                Note that Byteman uses the internal name using the $ separator to identify inner classes (n.b. it's all very well for Java but for Byteman a '.' would look like a package separator identifying class JMXHelperAux of package JMXHelper).

                 

                Ok, so now we need to create a private static inner class inside JMXHelper and create static methods that the transplant the behaviour of the existing JMXHelper methods so they can be redirected:

                 

                class JMXHelper {
                  . . .
                  class JMXHelperAux {
                    private static KeyInfo keyInfo()
                    {
                        // if the rule set does not generate a keyinfo value then we return this one to indicate
                        // that something is missing.
                        String[] keyNames = new String[1];
                        keyNames[0] = "No counters defined";
                        return new KeyInfo("Byteman Periodic Statistics", keyNames);
                    }
                    . . .
                  }
                  . . .
                  etc

                 

                Finally, redefine the corresponding methods of JMXHelper so they indirect to the aux class:

                 

                class JMXHelper {
                  . . .
                  private KeyInfo keyInfo()
                  {
                        return JMXHelperAux.keyInfo();
                  }
                  . . .

                 

                Class JMXHelper will still be loaded when the rules for Thread etc get injected. However, that won't cause a problem because the new ruels are injected into class JMXHelper.JMXHelperAux which gets loaded during normal running of the PeriodIcHelperThread under initialise().

                 

                Hope that helps.

                 

                regards,

                 

                 

                Andrew Dinn

                1 of 1 people found this helpful