Runtime profiling and monitoring Java apps with btrace
Wednesday, May 28th, 2008A the latest Genova JUG meeting last week there was much discussion about performance tuning and optimization, particularly of web applications. My mention of the recently released BTrace profiling tool was met with significant interested and I was asked to provide more details and references…
BTrace (where the ‘B’ stands for bytecode) is an open source tool hosted on java.net, where you can find extensive documentation and samples. It is conceptually similar to the much-talked-about Solaris DTrace platform, but can be used on any Java platform/app.
The main BTrace concept is that of dynamically connecting to a running Java application (or server) to attach short “scripts” which log a range of events and infos such as
- method calls;
- execution times;
- constructor invocation;
- available memory;
Script execution is tied to several situations
- reaching a specific line number;
- invoking a given method;
- returning from a method;
- invoking system calls (e.g. exit);
- recurring timer (period execution at fixed intervals);
- and many more…
In a way, BTrace scripts are very similar to AOP’s aspects, but can be attached to any existing Java code (or better, bytecode) at runtime and without any configuration or modification at development time.
The scripts are simply Java classes which take advantage of methods from the btrace API, and are configured by using simple but powerful annotations. Here you are an hello world script which traces session creation in hibernate:
// import BTrace annotations
import com.sun.btrace.annotations.*;
// import logging methods
import static com.sun.btrace.BTraceUtils.*;
@BTrace
public class HelloWorldTrace {
// probe the openSession() method of Hibernate SessionFactory
@OnMethod(
clazz=”org.hibernate.SessionFactory”,
method=”openSession”
)
public static void onOpenSessionTrace() {
// you can only log using the stati println method from BTraceUtils
println(”Hibernate: opening a new session…”);
}
}
Btrace scripts are attached to the running process using the JVM’s instrumentation interface.
If you are using JDK 1.6, you can attach to any running jvm by simply specifying its pid obtained through the new jps command:
jps 18037 Demo.JAR 19032 jps 19025 tomcat btrace 19025 HelloWorldTraceHibernate: opening a new session...Hibernate: opening a new session...
The last command is simply an utility batch file which actually compiles and attaches the script.: On the other hand, on previous JDKs it is necessary to enable tracing in a similar way to how you enable remote debugging.
As an example of BTrace power and ease of use, the following script from BTrace samples intercepts all calls to methods in classes which are annotated with @WebService (e.g. all JAX-WS web service classes) and logs theri execution times:
@BTrace public class WebServiceTracker {
// store webservice entry time in this thread local
@TLS private static long startTime;
@OnMethod(
clazz="@javax.jws.WebService",
method="@javax.jws.WebMethod"
)
public static void onWebserviceEntry() {
print("entering webservice ");
println(strcat(strcat(name(probeClass()), "."), probeMethod()));
startTime = timeMillis();
}
@OnMethod(
clazz="@javax.jws.WebService",
method="@javax.jws.WebMethod",
location=@Location(Kind.RETURN)
)
public static void onWebserviceReturn() {
println(strcat("Time taken (msec) ", str(timeMillis() - startTime)));
println("==========================");
}
}
Note the use of BTrace built-in strcat function, which is needed to avoid the overhead of string concatenation. Obviously, the script code must be as lightweight as possible to avoid influencing tracing results with its own execution times, and thus the BTrace API provides efficient implementations of basic logging tasks.
Stay tuned for more tracing examples…
