/dev/websphere

Instrumenting a Loader with BTrace

This is a script for measuring and timing the get/batchupdate and commit methods on a Loader implementation and its associated TransactionCallback. The lack of the ability to factor the code and invoke methods is why the timing code is copy and pasted in the return methods. btrace doesn't allow factoring...

Download PQLoaderTimer

BTrace experience continued

Trying to write a btrace script for measuring Loader performance. Time and count calls to the Loader.get and Loader.batchUpdate methods. This is doable pretty easy but it points out some limitations.

    @OnMethod(clazz = "purequery.loader.GenericPQLoader", method = "get", location = @Location(Kind.RETURN))

    public static void onCallMapAgentReturn() 

    {

        if (executingVerb != null) {

            AggregationKey key = newAggregationKey(executingVerb);

            int duration = (int) (timeNanos() - timeStampNanos) / 1000;

            BTraceUtils.print("Duration of "); BTraceUtils.print(executingVerb); BTraceUtils.print(" "); BTraceUtils.println(duration);

            addToAggregation(histogram, key, duration);

            addToAggregation(average, key, duration);

            addToAggregation(max, key, duration);

            addToAggregation(min, key, duration);

            addToAggregation(sum, key, duration);

            addToAggregation(count, key, duration);

            addToAggregation(globalCount, duration);

            executingVerb = null;

        }

    }

This code basically adds measurements for the verb measurementVerb to the stats. You need this code called when we leave the Loader.get or Loader.batchUpdate methods. The executionVerb indicates whether it's a get or a batchupdate. My first attempt at this put most of that method in a seperate static method called by the onGetReturn and onBatchUpdateReturn methods. This was rejected by the btracec compiler because you can only call BTraceUtils methods in the script. This restriction will quickly make scripts very big and hard to maintain as you end up copy and pasting the same code in a bunch of places.

Running btrace on multiple JVMs on a single box

It looks like the btrace java agent opens a socket on port 2020. Running two JVMs causes a port conflict and the agent doesn't initialize in the second or third JVMs. You can specify a port on the second JVM to avoid these conflicts using something like this:

-javaagent:/Users/bnewport/Development/btrace-bin/build/btrace-agent.jar=script=AgentServerTimer.class,port=2021

Just make sure each JVM uses a different port. Another issue is the agent writes the script logs to a file named after the agent. If two JVMs use the same script then you get both processes trying to open the same file and that won't work. For now, I'm not hitting this as I use one script for the client JVM (measuring calls to invoke agents) and another with a different name on the server JVM to measure the times to invoke the actual agents.

Client script: Download AgentTimer

Server script: Download AgentServerTimer

This lets me see the time on the client versus the actual time to run the agent server side. But, it will only work on a single client/single server JVM on a single box for now. You can work around this by copying the scripts around or using multiple boxes but maybe they should include the pid or port number in the file name.

btrace for performance tuning

Been playing with btrace this weekend. Very cool utility for adding performance monitoring to methods using weaving and aspects. It's pretty easy to use. You write a script which is a Java class which specifies the classes and methods you want watched. There are restrictions on what you can do in the methods called when a method is called or returns but it's flexible enough.

I'm attaching a script that times all Agent class made from a client. It prints them out by Agent class every 20 seconds. The script needs to be compiled with the btracec utility like this:

./../btrace-bin/bin/btracec -cp ../lib/objectgrid.jar AgentTimer.java

 

This creates an AgentTimer.class file which is the compiled form of the script

Now, run the client JVM but add this to the command line:

-javaagent:/Users/bnewport/Development/btrace-bin/build/btrace-agent.jar=script=AgentTimer.class

When you run the client, an AgentTimer.class.btrace file is created in the same directory as the AgentTimer.class file. This is where all the output goes.

The output looks like this:

Count

  redis.agent.list.LTrim                                            3

  redis.agent.Set                                                   3

  redis.agent.Incr                                                  3

  redis.agent.list.Push                                             6

  redis.agent.set.SetCard                                          14

  redis.agent.set.SetMembers                                       17

  redis.agent.list.LRange                                          18

Min

  redis.agent.list.LRange                                        4743

  redis.agent.set.SetCard                                        6221

  redis.agent.list.LTrim                                         6562

  redis.agent.set.SetMembers                                     6582

  redis.agent.list.Push                                          7549

  redis.agent.Incr                                               9445

  redis.agent.Set                                               11536

Max

  redis.agent.list.LTrim                                        10037

  redis.agent.list.Push                                         12034

  redis.agent.set.SetCard                                       16798

  redis.agent.Set                                               25215

  redis.agent.set.SetMembers                                    28472

  redis.agent.Incr                                              33212

It times each CallMapAgent call and plots all the results in a histogram. Very handy. I also print out the duration of each call.

I'll do more playing around with this. I was unable to get it to attach scripts dynamically to a running JVM. It only works for me when I use the agent approach to specify a script.

Download AgentTimer