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 log4j or the
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
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 "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.
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).
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.
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.
"Speeding
up Log4J in Java 5" by Inigo Surguy explains how to use
instrumentation to remove those log statements that are not
enabled at class-load time. Similar to this agent, but requires log
statements to be present in the code.
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.
What did you think of this introduction to instrumentation?
Showing messages 1 through 5 of 5.
wouldn't aspectj be a better choice ?
2008-04-27 01:13:49 tomek_k
[Reply | View]
i wonder if you aspectj is not the better (the best ?) tool for this kind of job
Tomek Kaczanowski
wouldn't aspectj be a better choice ?
2008-04-27 02:37:11 ravn
[Reply | View]
Aspectj works as part of compiling your source, and I agree that this is probably a great thing to use if it is suitable for your development habits.
The agent approach allows you to instrument classes without any recompilation and redeployment.
This provide another way to investigate issues with code where you do not have the source or where redeployment is out of the question. You may not have access to a debugger, even. Has happened to me.
wouldn't aspectj be a better choice ?
2008-04-29 12:11:29 thofoer
[Reply | View]
You can do this easily by Load-Time-Weaving and AspectJ.
One Hint:
JavassistHelper, Line 62 will fail with a NullPointerException if $i is null.
Replaced it for me with sb.append("\"+ String.valueOf($" + (i + 1) + ")");
Add Logging at Class Load Time with Java Instrumentation
java.net RSS Feeds
