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

Comments

[A.O.P I am tired of technology]

Is the AgentManager interface implemented by multiple classes? Are calls to such implementations nested?

[Billy Newport]

No, but rather than specify in a public blog entry the actual class name of the implementation, it seems better to just say anything that implements AgentManager which should just be the ibm runtime and this will always work even if we changed the impl class name. Only issue of course, is someone proxying it but they can then just make more specific scripts.

[A.O.P I am tired of technology]

It is worth pointing out to others that this script if ported to another problem context would give completely incorrect (understated) results if there was indeed nesting of calls matching the same probe point. You would be over-writing the timestamp (static) field in a nested call. Is this not the case?

[Billy]

Yep
The more I use it, the scripts are extremely limited. Not being able to call static methods for common sections of code means extensive copy and paste with the associated head aches on maintenance and readability.

[A.O.P I am tired of technology]

Once you go beyond the hello world examples you will quickly realize that it is fundamentally broken not to mention that its overhead in the context of performance measurement (aggregation) is not just huge it is colossal.

The first rule in software performance engineering is always measure the tool's overhead ** first ** before giving any due consideration to the data report. You failed the test. Next.....

[Billy Newport]

I'm finding very little difference in performance between running with it or without it. So, I think what ever axe you have to grind then it'd be nice if you just said. While it's cool to shoot arrows when you're anonymous, it carries a lot more weight when people know who you are and what the agenda is.

Thanks

[Billy Newport]

I guess to put further context on this. This is a very simple tool. It does not do what jxinsight does or a Wily introscope. For just kicking something around, its easy to use and you can get numbers out in minutes. I'd still recommend jx or even wily once you get to cluster of things or 'production'.

[A.O.P I am tired of technology]

An average overhead of 16 microseconds per method seems high to me if applied to a sufficiently large code (not just a single method) base with eXtreme performance requirements. Not to mention the fact that you will very quickly get integer overflow in the aggregation which is ** int ** based as you have clearly found out above.

"There are only two ways of telling the complete truth --anonymously and posthumously."