Java Instrumentation, javaassist and a new hero Mr.Ted Neward

One of the most interesting sessions that I attended at NFJS was by Ted Neward called " The Busy Java Developer's Guide to Hacking (on) the JDK". I found Mr.Neward to be a very engaging speaker. One of the topics he covered during the session was how to agument java byte code dynamically and the use of the java instrumentation API. I have not directly had a chance to play/work with the same. Regarding byte code enhancement, asm does that and I have used libraries that utilize the same.

Mr.Neward introduced me to javassist, a neat tool to perform byte code augmentation at run time. Based of the same, I have below a simple Maven project that attempts to profile classes.

Keeping the scope simple, the example will only profile classes that are part of the package "com.welflex" and beyond. The code will point out when a method is entered and upon exit of the method and will also print out the time taken for the execution of the method.

The strategy used is that the original method is dynamically replaced with a method that the proxy will delegate to. The original method is named differently (with an impl) and the new proxy method takes the place of the original method and proxies to the new method.

The example is based of maven multi-module project. There are two modules, the first being the actual profiler and the second is an example that will be profiled.

.
-- pom.xml
-- profiler-instrumentation
   -- pom.xml
   `-- src
       `-- main
           -- java
                  `-- welflex
                      `-- instrumentation
                          `-- ProfilerClassFileTransformer.java
           `-- resources
               `-- META-INF
                   `-- MANIFEST.MF
`-- profiler-target
  -- pom.xml
  `-- src
      `-- main
          `-- java
              `-- com
                  `-- welflex
                      `-- profiletarget
                          -- Application.java
                          `-- Description.java

To start of, we define an implementation of the ClassFileTransformer called ProfilerClassTranformer whose core method shown below is responsible for replacing the byte code:

private void addProfilingInformation(CtClass clas, CtMethod mold) throws NotFoundException,
 CannotCompileException {
 // get the method information (throws exception if method with
 // given name is not declared directly by this class, returns
 // arbitrary choice if more than one with the given name)
 String mname = mold.getName();
 String longName = mold.getLongName();

 // rename old method to synthetic name, then duplicate the
 // method with original name for use as interceptor
 String nname = mname + "$impl";

 mold.setName(nname);
 CtMethod mnew = CtNewMethod.copy(mold, mname, clas, null);

 // start the body text generation by saving the start time
 // to a local variable, then call the timed method; the
 // actual code generated needs to depend on whether the
 // timed method returns a value
 String type = mold.getReturnType().getName();
 StringBuffer body = new StringBuffer();
 body.append("{\n");
 body.append("int currentStackDepth = Thread.currentThread().getStackTrace().length;\n");
 body.append("StringBuffer buf = new StringBuffer();");
 body.append("for (int zs = 0; zs < currentStackDepth; zs++) {")
   .append("buf.append(\"   \");\n")
   .append("}");

 body.append(" System.out.println(buf.toString() + \"-> Enter Method:" + longName + "\");\n");
 body.append(" long startTime = System.nanoTime();\n");
 body.append("try {\n");

 if (!"void".equals(type)) {
   body.append(type + " result = ");
 }

 body.append(nname + "($$);\n");

 if (!"void".equals(type)) {
   body.append("return result;\n");
 }

 body.append("} finally {");
 // finish body text generation with call to print the timing
 // information, and return saved value (if not void)
 body.append("long endTime = System.nanoTime();\n");
 body.append("long delta = endTime - startTime;\n");

 body.append("System.out.println(buf.toString() + \"<- Exit Method:" + longName +
   " completed in \" + delta + \" nano secs\");\n");

 body.append(" }\n");
 body.append("}");

 // replace the body of the interceptor method with generated
 // code block and add it to class
 mnew.setBody(body.toString());
 clas.addMethod(mnew);
}

The code utilizes javassist in augmenting the original methods with profiling information. The target jar produced has a references to the javaassist.jar through the MANIFEST.MF (thanks to my boss for reminding Ted Neward of the same).

The above code should be rather simple to follow where the original method is being replaced by the "Aspect" like code. After downloading the project, issue a "mvn install" command to install the modules. I have additionally provided a ZIP file containing the resultant jars HERE.

In order to ensure that the profiler is applied on the code base, the following java command is executed from within a folder that contains the profiler-instrumentation, javaassist and profiler-target jars as shown below:

java -javaagent:./profiler-instrumentation-1.0-SNAPSHOT.jar -classpath .:profiler-target-1.0-SNAPSHOT.jar com.welflex.profiletarget.Application
     -> Enter Method:com.welflex.profiletarget.Application.main(java.lang.String[])
           -> Enter Method:com.welflex.profiletarget.Description.setDescription(java.lang.String)
           <- Exit Method:com.welflex.profiletarget.Description.setDescription(java.lang.String) completed in 10415 nanosecs
           -> Enter Method:com.welflex.profiletarget.Application.rest()
           <- Exit Method:com.welflex.profiletarget.Application.rest() completed in 1000072374 nano secs
           -> Enter Method:com.welflex.profiletarget.Application.rest(long)
           <- Exit Method:com.welflex.profiletarget.Application.rest(long) completed in 3000058065 nano secs
           -> Enter Method:com.welflex.profiletarget.Application.getDescription()
                 -> Enter Method:com.welflex.profiletarget.Description.getDescription()
                 <- Exit Method:com.welflex.profiletarget.Description.getDescription() completed in 5265 nano secs
           <- Exit Method:com.welflex.profiletarget.Application.getDescription() completed in 207834 nano secs
Descripion of App:Simple App
     <- Exit Method:com.welflex.profiletarget.Application.main(java.lang.String[]) completed in 4037331452 nano secsva

As seen above the key is to specify a "javaagent" via the "-javaagent" argument to the VM. As shown above that although the profiler-target code did not have any profiling information, we were able to instrument the same at run time using javaassist and the Java Instrumentation library. The above execution shows how long each method took to execute.

The MAVEN project for the profiler can be found HERE . I am running the example with JDK1.6.X and Maven 2.0.8.

The code is largely based of the following two fantastic blogs/articles:
Java Programming Dynamics, Part 4 by Dennis Sosnoski and
Add Logging at Class Load Time with Java Instrumentation by Thorbjørn Ravn Andersen

If you have problems accessing the source or running the example..ping me. Thaks Mr.Neward..I have such a long way to go...the more I learn, there is still so much more to learn (please don't count the unlearn part) ! The "Force is infinite, I am not yet ready for the Jedi Council", I am still a Padwan! But...a Happy Padwan at that :-)))!