Skip to main content

Add Logging at Class Load Time with Java Instrumentation

April 24, 2008

{cs.r.title}






When you're trying to analyze why a program failed, a very valuable
piece of information is what the program was actually doing when it failed. In many cases, this can be determined with a stack trace, but
frequently that information is not available, or perhaps what you
need is information about the data that was being processed at the
time of failure.

Traditionally this means using a logging framework like "http://logging.apache.org/log4j/">log4j or the "http://java.sun.com/javase/6/docs/api/java/util/logging/package-summary.html">
Java Logging API
, and then writing and maintaining all
necessary log statements manually. This is very tedious and error-prone, and well-suited for automation. Java 5 added the "http://java.sun.com/javase/6/docs/api/java/lang/instrument/Instrumentation.html">
Java Instrumentation
mechanism, which allows you to provide
"Java agents" that can inspect and modify the byte code of the
classes as they are loaded.

This article will show how to implement such a Java agent, which
transparently will add entry and exit logging to all methods in all
your classes with the standard Java Logging API. The example used
is Hello World:

public class HelloWorld {
    public static void main(String args[]) {
        System.out.println("Hello World");
    }
}

And here is the same program with entry and exit log statements
added:

import java.util.Arrays;
import java.util.logging.Level;
import java.util.logging.Logger;

public class LoggingHelloWorld {
    final static Logger _log = Logger.getLogger(LoggingHelloWorld.class.getName());

    public static void main(String args[]) {
        if (_log.isLoggable(Level.INFO)) {
            _log.info("> main(args=" + Arrays.asList(args) + ")");
        }
        System.out.println("Hello World");
        if (_log.isLoggable(Level.INFO)) {
            _log.info("< main()");
        }
    }
}

The default logger format generates output similar to:

2007-12-22 22:08:52 LoggingHelloWorld main
INFO: > main(args=[])
Hello World
2007-12-22 22:08:52 LoggingHelloWorld main
INFO: < main()

Note that each log statement is printed on two lines. First, a
line with a time stamp, the provided log name, and the method in
which the call was made, and then a line with the provided log
text.

The rest of the article will demonstrate how to make the
original Hello World program behave like the logging Hello World by
manipulating the byte code when it is loaded. The manipulation
mechanism is the Java Instrumentation API added in Java 5.

Using the Java Instrumentation API

You can invoke Java with the JVM arguments
-javaagent:youragent.jar or
-javaagent:youragent.jar=argument to have Java call
the premain(...) method listed in the manifest of
youragent.jar before trying to run the main
method specified. This premain(...) method then allows
you to register a class file transformer with the system
class loader, which provides a transform(...) method.
This method is then called as a part of loading each and every
class from then on, and may manipulate the actual byte codes before
it is processed by the class loader into a real
Class.

For this to work you must have several pieces in place:

A class implementing
ClassFileTransformer.
The transform(...) method will be called for each
class as it is being loaded. The argument is the complete, original
byte code for the whole class.
A class providing a static void premain()
method.
The premain(...) method must register the above
transformer with the class loader. It can also handle the argument
provided at the command line.
A correct MANIFEST.MF file.
The MANIFEST.MF must contain a Pre-Class: .. line
referring to the class with the premain() method.
Additionally, use Boot-Class-Path: to refer to external .jar
files.

The code must be put into a .jar file with this manifest. If not,
it will silently fail.

The com.runjva.instrumentation.LoggerAgent Sample
Agent

This section lists a sample agent named
com.runjva.instrumentation.LoggerAgent. It implements
the java.lang.instrument.ClassFileTransformer
interface and provides the premain(...) method
required.

The actual byte code manipulation in the
transform(...) method is done with the JBoss "http://www.jboss.org/javassist/">"Javassist" library, which
provides both a Java snippet compiler and high-level byte code
manipulation routines. The compiler allows us to do the
manipulation by creating Java string snippets that are then
compiled and inserted at the appropriate location.

The signature extraction and return value type extraction
methods are rather complex and have been placed in
com.runjva.instrumentation.JavassistHelper, which is
not listed but available in the sample code .zip file.

See the Resources section for the
sample code and links to Javassist and background articles.

This is the com.runjva.instrumentation.LoggerAgent
class:

package com.runjva.instrumentation;

import java.lang.instrument.*;
import java.util.*;
import javassist.*;

public class LoggerAgent implements ClassFileTransformer {

  public static void premain(String agentArgument,
      Instrumentation instrumentation) {
    if (agentArgument != null) {
      String[] args = agentArgument.split(",");
      Set argSet = new HashSet(Arrays.asList(args));

      if (argSet.contains("time")) {
        System.out.println("Start at " + new Date());
        Runtime.getRuntime().addShutdownHook(new Thread() {
          public void run() {
            System.out.println("Stop at " + new Date());
          }
        });
      }
      // ... more agent option handling here
    }
    instrumentation.addTransformer(new LoggerAgent());
  }

The premain(...) method is responsible for adding
the LoggerAgent as a class transformer. It also
considers the string argument as a comma-separated list of options
and if the option time is given, the date is printed now and at
shutdown time.


  String def = "private static java.util.logging.Logger _log;";
  String ifLog = "if (_log.isLoggable(java.util.logging.Level.INFO))";

  String[] ignore = new String[] { "sun/", "java/", "javax/" };

  public byte[] transform(ClassLoader loader, String className,
      Class clazz, java.security.ProtectionDomain domain,
      byte[] bytes) {

    for (int i = 0; i < ignore.length; i++) {
      if (className.startsWith(ignore[i])) {
        return bytes;
      }
    }
    return doClass(className, clazz, bytes);
  }

The transform(...) method is called for every class
loaded by the system class loader just before being instantiated
into a real object. Each class contains code to load those classes
it needs, so to avoid adding loggers to the runtime library classes,
it is necessary to look at the class name and return library
classes unmodified (note that the separators are slashes, not
dots).


  private byte[] doClass(String name, Class clazz, byte[] b) {
    ClassPool pool = ClassPool.getDefault();
    CtClass cl = null;
    try {
      cl = pool.makeClass(new java.io.ByteArrayInputStream(b));
      if (cl.isInterface() == false) {

        CtField field = CtField.make(def, cl);
        String getLogger = "java.util.logging.Logger.getLogger("
            + name.replace('/', '.') + ".class.getName());";
        cl.addField(field, getLogger);

        CtBehavior[] methods = cl.getDeclaredBehaviors();
        for (int i = 0; i < methods.length; i++) {
          if (methods[i].isEmpty() == false) {
            doMethod(methods[i]);
          }
        }
        b = cl.toBytecode();
      }
    } catch (Exception e) {
      System.err.println("Could not instrument  " + name
          + ",  exception : " + e.getMessage());
    } finally {
      if (cl != null) {
        cl.detach();
      }
    }
    return b;
  }

The doClass(...) method uses Javassist to analyze
the byte stream provided. If it is a real class (as opposed to an
interface), a logger field named _log is added and
initialized to the name of the class. Each non-empty method is then
processed with doMethod(...). The
finally clause ensures that the class definition is
removed again from the Javassist pools to keep memory usage
down.


  private void doMethod(CtBehavior method)
      throws NotFoundException, CannotCompileException {

    String signature = JavassistHelper.getSignature(method);
    String returnValue = JavassistHelper.returnValue(method);

    method.insertBefore(ifLog + "_log.info(">> " + signature
        + ");");

    method.insertAfter(ifLog + "_log.info("<< " + signature
        + returnValue + ");");
  }
}

The doMethod(...) class creates

if
(_log.isLoggable(INFO))_log.info(...)
snippets to insert at
the beginning and end of each method. This level has been chosen as
it is the lowest level that generates output without any
configuration of the logging system.

Note that the JavassistHelper class is available in
the sample code .zip file (see "#resources">Resources).

The Sample MANIFEST.MF File

Only two lines are needed here: one to point to the class with
the premain method, and one to make Javassist
available to the agent.

Premain-Class: com.runjva.instrumentation.LoggerAgent
Boot-Class-Path: ../lib/javassist.jar

Note that the dist/loggeragent.jar needs to
lib/javassist.jar--hence the ../lib relative
path.

The Sample build.xml File

The build.xml file contain a compilation target, a .jar
target, a traditional HelloWorld target, and a
HelloWorld target with the logger agent active.

<project name="Logger Agent (Java 5+)" default="all">
  <target name="all" depends="compile,jar,withoutAgent,withAgent"/>

  <target name="withAgent" description="run with logging added by java agent">
    <java fork="yes" classpath="bin" classname="com.runjva.demo.HelloWorld">
      <jvmarg value="-javaagent:dist/loggeragent.jar=time"/>
    </java>
  </target>

  <target name="withoutAgent" description="run normally">
    <java fork="yes" classpath="bin" classname="com.runjva.demo.HelloWorld">
    </java>
  </target>

  <target name="compile" description="compile classes">
    <delete dir="bin" />
    <mkdir dir="bin" />
    <javac source="1.4" srcdir="src" destdir="bin" debug="true" 
              optimize="true" verbose="false" classpath="lib/javassist.jar">
    </javac>
  </target>

  <target name="jar" depends="compile" description="create agent jar">
    <jar basedir="bin" destfile="dist/loggeragent.jar" manifest="Manifest.mf"/>
  </target>
</project>

Running ant gives output similar to:


Buildfile: build.xml

compile:
   [delete] Deleting directory /home/ravn/workspace/com.runjva.instrumentation/bin
    [mkdir] Created dir: /home/ravn/workspace/com.runjva.instrumentation/bin
    [javac] Compiling 3 source files to /home/ravn/workspace/com.runjva.instrumentation/bin

jar:
      [jar] Building jar: /home/ravn/workspace/com.runjva.instrumentation/dist/loggeragent.jar

withoutAgent:
     [java] Hello World

withAgent:
     [java] Start at Fri Apr 18 21:13:53 CEST 2008
     [java] 18-04-2008 21:13:54 com.runjva.demo.HelloWorld main
     [java] INFO: >> main(args=[])
     [java] Hello World
     [java] 18-04-2008 21:13:54 com.runjva.demo.HelloWorld main
     [java] INFO: << main(args=[])
     [java] Stop at Fri Apr 18 21:13:54 CEST 2008

all:

BUILD SUCCESSFUL
Total time: 2 seconds

The output shows that the logging statements have been
added and that they actually generate output. The actual order of
the statements may change from run to run, as the log statements
are written to System.err and the timing info, as well
as the output from HelloWorld, is written to
System.out.

Conclusion

The Java Instrumentation API can be used to transparently add
method-call logging to any Java code at runtime without changing
the source code or the compiled byte code. By automating the
generation of log statements, it is guaranteed that they are always
up to date and the programmers are relieved of this tedious
task.

Resources


width="1" height="1" border="0" alt=" " />
Thorbjørn Ravn Andersen is a Senior Software Engineer who creates web services, frontends and helper programs for legacy Cobol applications in Java on the IBM iSeries.
Related Topics >> Programming   |   

Comments

A simple/straightforward and

A simple/straightforward and well-written article. Nice intro to how the instrumentation framework works ... with code. Thanks! Kiran Bhogadi

I found this article very useful and implemented an improved ...

I found this article very useful and implemented an improved version of the LoggerAgent.

The class from the article requires that javasist.jar and all other files needed to compile the inserted java code are added to the bootstrap class path. It is particularly bad if the solution is used in applications with many class loaders or if the libraries the compiled code depend on should not be on the bootstrap class path because of any other reasons. Debugging of the transformer classes in IDE is also more difficult in this case.

Therefore I split the LoggerAgent in two different classes, the agent and the transformer. Here is my solution:

import java.lang.instrument.ClassFileTransformer;
import java.lang.instrument.Instrumentation;
import java.util.HashMap;
import java.util.Map;

public class LoggerAgent implements ClassFileTransformer {

    private static String transformerClass = null;
    private Map<ClassLoader, ClassFileTransformer> transformers = new HashMap<ClassLoader, ClassFileTransformer>();
    private String[] ignore = new String[] { "sun/", "com/sun/", "java/", "javax/" };
    public static void premain(String agentArgument,
            Instrumentation instrumentation){
        transformerClass = agentArgument;
        instrumentation.addTransformer(new LoggerAgent());
    }

    public byte[] transform(ClassLoader loader, String className,Class<?> clazz, java.security.ProtectionDomain domain,  byte[] bytes) {
        try {
            // skip bootstrap classes
            if(loader == null)
                return bytes;
            // skip java runtime classes
            for (String ignored : ignore) {
                if (className.startsWith(ignored)) {
                    return bytes;
                }
            }
            ClassFileTransformer transformer = transformers.get(loader);
            if(transformer == null){
                transformer = (ClassFileTransformer) loader.loadClass(transformerClass).newInstance();
                transformers.put(loader, transformer);
            }
            return transformer.transform(loader, className, clazz, domain, bytes);
        } catch (Exception e) {
            e.printStackTrace();
        }
        return bytes;
    }
}

The manifest does not require the Boot-Class-Path: ../lib/javassist.jar any more

The class actually used for the transformation should be set as an argument of premain(...) .

-javaagent:dist/loggeragent.jar=the.actual.transofmer.class.from.the.class.path.TheTransformer

This solution instantiates different transformer objects for each class loader the transform is called.

Regards,

Dimitry Polivaev

I really like the article and hope to solve a problem this ...

I really like the article and hope to solve a problem this path. It would be very helpful if the sample project was still available.
Could you please let me know where to download it?

TIA

Frank

...

...

Excellent article. Source link seems to be messed up, ...

Excellent article. Source link seems to be messed up, however. I found it here (http://today.java.net/today/2008/04/24/com.runjva.instrumentation.zip).