Sunday, May 5, 2013

Java instrumentation tutorial

This article explains how Java instrumentation works, and how you can write your own agent to do some basic profiling/tracing.

Overview

JVM instrumentation feature was introduced in JDK 1.5 and is based on byte code instrumentation (BCI). Actually, when a class is loaded, you can alter the corresponding byte code to introduce features such as methods execution profiling or event tracing. Most of Java Application Performance Management (APM) solutions use this mechanism to monitor JVM.

Instrumentation Agent

To enable JVM instrumentation,  you have to provide an agent (or more) that is deployed as a JAR file. An attribute in the JAR file manifest specifies the agent class which will be loaded to start the agent.

There is 2 ways to load the agent:
  • with a command-line interfaceby adding this option to the command-line: -javaagent:jarpath[=options] where jarpath is the path to the agent JAR file. options is the agent options. This switch may be used multiple times on the same command-line, thus creating multiple agents. More than one agent may use the same jarpath.
  • by dynamic loading: the JVM must implement a mechanism to start agents sometime after the the VM has started. That way, a tool can "attach" an agent to a running JVM (for instance profilers or ByteMan)


After the JVM has initializedthe agent class will be loaded by the system class loader. If the class loader fails to load the agent, the JVM will abort.



Next, the JVM instantiates an Instrumentation interface implementation and given the context, tries to invoke one of the two methods that an agent must implement: premain or agentmain.

The premain method is invoked after JVM initialization and the agentmain method is invoked sometime after the JVM has started (if the JVM provides such a mechanism). When the agent is started using a command-line option (with -javaagent), the agentmain method is not invokedThe agent class may also have a premain method for use when the agent is started using a command-line option. When the agent is started after JVM startup the premain method is not invoked.




The signatures of the premain method are:
public static void premain(String agentArgs, Instrumentation inst);
public static void premain(String agentArgs);

And the signatures of the agentmain method are:
public static void agentmain(String agentArgs, Instrumentation inst);
public static void agentmain(String agentArgs);
The agent needs to implement only one signature per method.  The JVM first attempts to invoke the first signature, and if the agent class does not implement it then the JVM will attempt to invoke the second signature.

Byte Code Instrumentation

With the premain and agentmain methods, the agent can register a ClassFileTransformer instance by providing an implementation of this interface in order to transform class files. To register the transformer, the agent can use the addTransformer method of the given Instrumentation instance.


Now, all future class definitions will be seen by the transformer, except definitions of classes upon which any registered transformer is dependent. The transformer is called when classes are loaded, when they are redefined. and optionally, when they are retransformed (if the transformer was added to the instrumentation instance with the boolean canRetransform set to true).

The following method of the ClassFileTransformer interface is responsible of any class file transformation:
byte[] transform(ClassLoader loader, String className, Class<?> classBeingRedefined,
                 ProtectionDomain protectionDomain, byte[] classfileBuffer);

This is where things get complicated because you need to manipulate raw byte code. To achieve this, i strongly suggest to rely on dedicated tools such as ASM or Javassist.

Basic Profiling

To illustrate how the class file transformer can be used, we are going to set up some basic method profiling with Javassist:
  1. Write a trivial class that will be instrumented
  2. Write a ClassFileTransformer to inject some code to print method execution time
  3. Write an agent that registers the previous transformer
  4. Write the corresponding JUnit test
The class to be instrumented is:
package org.javabenchmark.instrumentation;

public class Sleeping {
    
    public void randomSleep() throws InterruptedException {
        
        // randomly sleeps between 500ms and 1200s
        long randomSleepDuration = (long) (500 + Math.random() * 700);
        System.out.printf("Sleeping for %d ms ..\n", randomSleepDuration);
        Thread.sleep(randomSleepDuration);
    }
}

The transformer class is:
package org.javabenchmark.instrumentation;

import java.lang.instrument.ClassFileTransformer;
import java.lang.instrument.IllegalClassFormatException;
import java.security.ProtectionDomain;
import javassist.ClassPool;
import javassist.CtClass;
import javassist.CtMethod;

public class SleepingClassFileTransformer implements ClassFileTransformer {

    public byte[] transform(ClassLoader loader, String className, Class classBeingRedefined,
        ProtectionDomain protectionDomain, byte[] classfileBuffer) throws IllegalClassFormatException {

        byte[] byteCode = classfileBuffer;

        if (className.equals("org/javabenchmark/instrumentation/Sleeping")) {

            try {
                ClassPool cp = ClassPool.getDefault();
                CtClass cc = cp.get("org.javabenchmark.instrumentation.Sleeping");
                CtMethod m = cc.getDeclaredMethod("randomSleep");
                m.addLocalVariable("elapsedTime", CtClass.longType);
                m.insertBefore("elapsedTime = System.currentTimeMillis();");
                m.insertAfter("{elapsedTime = System.currentTimeMillis() - elapsedTime;"
                        + "System.out.println(\"Method Executed in ms: \" + elapsedTime);}");
                byteCode = cc.toBytecode();
                cc.detach();
            } catch (Exception ex) {
                ex.printStackTrace();
            }
        }

        return byteCode;
    }
}

The transformer checks if the class to transform is the Sleeping one, then it injects the code that prints the time elapsed by the execution of the randomSleep() method.

The agent class is:
package org.javabenchmark.instrumentation;

import java.lang.instrument.Instrumentation;

public class Agent {

    public static void premain(String agentArgs, Instrumentation inst) {
        
        // registers the transformer
        inst.addTransformer(new SleepingClassFileTransformer());
    }
}
And finally, the corresponding JUnit code:
package org.javabenchmark.instrumentation;

import org.junit.Test;

public class AgentTest {

    @Test
    public void shouldInstantiateSleepingInstance() throws InterruptedException {

        Sleeping sleeping = new Sleeping();
        sleeping.randomSleep();
    }
}
But, before executing the test you need to setup Maven to enable the JVM agent:
  • build the JAR that contains the agent's code before running test
  • add the JVM option -javagent to the JVM that runs the test
  • add the Javassist dependency
To achieve this, add the following XML code to your pom.xml file, inside the <build><plugins> ... </plugins></build> section:
            
            
                org.apache.maven.plugins
                maven-jar-plugin
                2.4
                
                    
                        process-classes
                        
                            jar
                        
                        
                            
                                
                                    org.javabenchmark.instrumentation.Agent
                                
                            
                        
                    
                
            

            
            
                org.apache.maven.plugins
                maven-surefire-plugin
                2.14
                
                    -javaagent:target/${project.build.finalName}.jar
                
            
Next, add the Javassist dependency:
        
            org.javassist
            javassist
            3.14.0-GA
            jar
        

Then, running the test should produce something like this:
-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running org.javabenchmark.instrumentation.AgentTest
Sleeping for 818 ms ..
Method Executed in ms: 820
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.001 sec
You can see that there is a new trace: Method Executed in ms: 820 proving that instrumentation works. Without instrumentation, you would only have the Sleeping for 818 ms .. trace.

Conclusion

It is easy to profile your code with the instrumentation API and the Javassist API: write transformers with Javassist, write an agent to register them, then use the -javaagent option and you're done !

21 comments:

  1. Thanks for this post - it is a great introduction to instrumentation!

    ReplyDelete
  2. Thanks for the article.
    Question left is - after dynamically loading a java agent (in order to add logs, or any other code), how can it be dynamically unloaded ? without restarting the JVM ofcourse...
    Or at least deactivate it, so it doesnt effect performance...

    ReplyDelete
    Replies
    1. As far as i know, there is no way to unload a java agent. To reduce overhead, i suggest you to had a flag in your intrumentation code to enable/disable it.

      Delete
  3. Replies
    1. I can't find the jar file for org.junit.Test.
      Could you publish it? Thanks

      Delete
    2. You can find it there: http://mvnrepository.com/artifact/junit/junit/4.11

      Delete
  4. Great article!

    After reading it, I immediately started a new (profiling) project, called unitprofiler. The idea is to annotate a junit test method, to profile all method invocations and then to create a nice visual presentation (html page in target directory)... It's still pre-alpha, but if anybody is interested, you can check http://unitprofiler.blogspot.de for news or have a look at the github project.

    ReplyDelete
    Replies
    1. I'm glad that the article inspired you ! Good luck with your Unit Profiler project !

      Delete
  5. My agent doesn't inject java Instrumentation object, so it's throw NullPointerException, thoughts ?

    ReplyDelete
  6. Very Nice Thoughts. Thanks For Sharing with us. I got More information about Java from Besant Technologies. If anyone wants to get Java Training in Chennai visit Besant Technologies.

    ReplyDelete
  7. Hi, i have been working on my FYP and stuck somewhere. My project is to generate Control Flow Graph of java code then calaculate cyclomatic complexity. For generating CFG i have to identify the blocks of java code.e.g
    User will provide java code as follows my my program will give output as follows:


    class A{//block1
    public static void main(String args[]){//block2
    int a=2;
    if(a>3)//block3
    .....
    }
    }

    Like this ....... i want my output.

    Any help will be very appreciative..
    I want to use some builtin API or plugin for this purpose.

    Thanks

    ReplyDelete
    Replies
    1. HI, i think that you should use an Abstract Syntax Tree (AST) for yout CFG. Find the right parser and start playing with the AST provided to compute the cyclomatic complexity. Hope that will help you.

      Delete
  8. I am trying to print when my application creates connection, open/close statement or prepared statement.
    But i am always getting exception: javassist.CannotCompileException: no method body.
    Is this due to Class type to be instrumented is Interface?
    How to instrument when we do not know the underlying class but my code calls by interface (Specifically java.sql.*)
    Your response is much appreciated!

    ReplyDelete
  9. Nice article! ;)

    ReplyDelete
  10. This is Yoda like Java programming, very high level. I just usually use some tools within eclipse to profile

    ReplyDelete
  11. Is it possible to attach java agent to the already running tomcat web application without shutting down tomcat?

    ReplyDelete
  12. Thanks for the nice article. It seems like there is some typo or maybe auto-correction for some of pom entities like artifactid insteadof artifiactId and manifestentries instead of manifestEntries, etc and it seems like those are leading compile to fail.

    ReplyDelete
  13. Very elegant way of profiling. Thanks!

    ReplyDelete