Monitoring your JVM using Byteman 1.1.1

Byteman is a bytecode injection tool developed to support testing of Java code using a technique called fault injection. However, it is also very useful for debugging and tracing Java program execution, including execution of the JVM itself. In this post I walk through an example Byteman script which monitors creation, start and exit of threads inside the JBoss Application Server.

The latest version of Byteman (1.1.1) has just been released and it includes the first batch in a series of sample Byteman scripts, all of which provide examples of how to monitor different aspects of JVM operation. The scripts inject tracing code into different JVM classes so that you can watch the JVM as it starts or stops threads, opens sockets, closes files, finalizes instances etc.

Seeing these scripts at work can be very educational -- for example, runnning up the JBoss App Server with script ThreadMonitor.txt installed I could see exactly which threads are created, started and stopped during AS bootstrap.

The script only needs 3 simple rules:

########################################################################
#
# Rule to trace thread creation
#

RULE ThreadMonitor trace create
CLASS java.lang.Thread
METHOD <init>
HELPER org.jboss.byteman.sample.helper.ThreadMonitorHelper
AT EXIT
IF TRUE
DO traceCreate($0)
ENDRULE

########################################################################
#
# Rule to trace thread start
#

RULE ThreadMonitor trace start
CLASS java.lang.Thread
METHOD start
HELPER org.jboss.byteman.sample.helper.ThreadMonitorHelper
AT EXIT
IF TRUE
DO traceStart($0)
ENDRULE

########################################################################
#
# Rule to trace thread exit
#

RULE ThreadMonitor trace exit
CLASS java.lang.Thread
METHOD exit
HELPER org.jboss.byteman.sample.helper.ThreadMonitorHelper
AT ENTRY
IF TRUE
DO traceExit($0)
ENDRULE

The first rule is injected into the constructor for java.lang.Thread, the second into Thread.start() and the third into Thread.exit(). The conditions are all TRUE because we want to see every call in the trace output. The rule actions call built-in methods traceCreate(Thread), traceStart(Thread) and traceExit(Thread),respectively. The argument to these calls, $0, is the thread object which is the target of the method invocation which triggers the rule, i.e. the one being created, started or exited. The built-in methods access this object to identify the thread's name and it's class name.

The implementation of the three trace methods is provided by a custom HELPER class, ThreadMonitorHelper, which specialises the library class StackTraceHelper provided in the sample lib jar. There is nothing special about this class -- it does not need to use Byteman library code to do its job. It is just a POJO which wraps up the code needed to print meaningful trace with a neat, simple API. All three methods print a line of text identifying the thread event (create, start or exit), thread name and thread class. The first two also use methods inherited from StackTraceHelper to look down the stack for the frame from which new Thread() or Thread.start() was called and print the details of the calling method.

Here's a sample of the output when running JBoss AS with these rules installed:

starting server default
=========================================================================

JBoss Bootstrap Environment

JBOSS_HOME: /home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT

JAVA: /usr/java/jdk1.6.0_14/bin/java

JAVA_OPTS: -Dprogram.name=run.sh -server -Xms600M -Xmx600M -XX:MaxPermSize=128m -Xdebug -Xnoagent -Djava.compiler=NONE -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=5005  -Dorg.jboss.byteman.quodlibet -javaagent:/home/adinn/byteman/install/lib/byteman.jar=listener:true,boot:/home/adinn/byteman/install/lib/byteman.jar,boot:/home/adinn/byteman/install/sample/lib/byteman-sample.jar,script:/home/adinn/byteman/install/sample/scripts/ThreadMonitor.txt -Djava.net.preferIPv4Stack=true

CLASSPATH: /home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/bin/run.jar:/usr/java/jdk1.6.0_14/lib/tools.jar

=========================================================================

*** Thread create JDWP Transport Listener: dt_socket java.lang.Thread
from VM runtime
Listening for transport dt_socket at address: 5005
*** Thread create JDWP Event Helper Thread java.lang.Thread
from VM runtime
*** Thread create CompilerThread0 java.lang.Thread
from VM runtime
*** Thread create CompilerThread1 java.lang.Thread
from VM runtime
*** Thread create Low Memory Detector java.lang.Thread
from VM runtime
*** Thread create main java.lang.Thread
from org.jboss.Main.main at Main.java:719
*** Thread start main java.lang.Thread
from org.jboss.Main.main at Main.java:719
*** Thread exit main java.lang.Thread
*** Thread create DestroyJavaVM java.lang.Thread
from VM runtime
*** Thread create Thread-1 java.util.logging.LogManager.Cleaner
from java.util.logging.LogManager$Cleaner.<init> at LogManager.java:200
*** Thread create Thread-2 org.jboss.Main.ShutdownHook
from org.jboss.Main$ShutdownHook.<init> at Main.java:883
12:38:16,588 INFO  [JBossASServerImpl] Server Configuration:

Bootstrap URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/conf/bootstrap.xml
JBOSS_HOME URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/
Common Base URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/common/
Common Library URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/common/lib/
Server Name: default
Server Base URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/
Server Library URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/lib/
Server Config URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/conf/
Server Home URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/
Server Data URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/data/
Server Log URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/log/
Server Temp URL: file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/tmp/

*** Thread create Thread-3 java.lang.Thread
from org.jboss.bootstrap.impl.base.server.AbstractServer.start at AbstractServer.java:350
*** Thread start Thread-3 java.lang.Thread
from org.jboss.bootstrap.impl.base.server.AbstractServer.start at AbstractServer.java:352
12:38:16,590 INFO  [AbstractServer] Starting: JBoss Server[6.0.0.SNAPSHOT (build: SVNTag=JBoss_6.0.0-SNAPSHOT date=r93729)]
12:38:17,344 INFO  [AbstractMCServerBase] Starting Microcontainer, Main bootstrapURL=file:/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/conf/bootstrap.xml
*** Thread create Thread-4 java.util.TimerThread
from java.util.TimerThread.<init> at Timer.java:456
*** Thread start Timer-0 java.util.TimerThread
from java.util.Timer.<init> at Timer.java:154
12:38:18,259 INFO  [VFSCacheFactory] Initializing VFSCache [org.jboss.virtual.plugins.cache.CombinedVFSCache]
12:38:18,262 INFO  [VFSCacheFactory] Using VFSCache [CombinedVFSCache[real-cache: null]]
12:38:18,670 INFO  [CopyMechanism] VFS temp dir: /home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/tmp
12:38:18,675 INFO  [ZipEntryContext] VFS force nested jars copy-mode is enabled.
*** Thread create Thread-5 java.util.TimerThread
from java.util.TimerThread.<init> at Timer.java:456
*** Thread start ZipFile Lock Reaper java.util.TimerThread
from java.util.Timer<init> at Timer.java:154

During this initial stage of bootstrap most of the threads are created by the VM itself. The first one actually created and started by the AS is identified by the following lines:

*** Thread create main java.lang.Thread
from org.jboss.Main.main at Main.java:719
*** Thread start main java.lang.Thread
from org.jboss.Main.main at Main.java:719
*** Thread exit main java.lang.Thread

The trace shows that the name of the newly created thread is main and it is an instance of class java.lang.Thread. It is created and immediately started by a call to Thread.start() in method org.jboss.Main.main at line 719 of file Main.java. Here's the actual code:

701       Runnable worker = new Runnable() {
702            public void run()
703            {
. . .
716            };
717
718       ThreadGroup threads = new ThreadGroup("jboss");
719       new Thread(threads, worker, "main").start();

The third trace line is a little confusing. The thread which has exited is not actually the JBoss main thread just created. It is in fact the parent thread, created by the VM and also called main. The JBoss main thread goes on to create a whole lot of other threads, connection handlers, pool threads and so on.

Clearly, there are lots of possibilities for developing alternative scripts which provide different, more interesting tracing behaviour. The other scripts in the samples directory provide further simple examples of how you might instrument other JVM classes to provide runtime trace. By coding more selective rule conditions or more complex rule sets it is possible to make the tracing much more fine-grained and specific to particular circumstances. Adding more actions, possibly using other custom helper classes, would allow a variety of different statistics to be gathered and displayed.

I will explain next how you set up your program to inject these rules. The trace above shows Byteman injecting the scripted rules from program start. However, when it comes to tracing execution it would be nice if it were possible to start up your program without any scripts installed and then switch on tracing by loading and unloading rules as needed. Well, of course, it is possible to do just and I'll go on to explain what you need to change to achieve that too.

First off let's run through how JBossAS was configured to start up the byteman agent and execute this script from JVM bootstrap. All that is needed is to supply the java command which starts the JBossAS Main class with a -javaagent argument. Passing this argument to JBossAS is most easily achieved by inserting it into environment variable JBOSS_OPTS ans the running the normal JBossAS startup script.

The actual setting required was displayed in one of the very long lines of trace output:

JAVA_OPTS: -Dprogram.name=run.sh -server -Xms600M -Xmx600M -XX:MaxPermSize=128m -Xdebug -Xnoagent -Djava.compiler=NONE -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=5005  -Dorg.jboss.byteman.quodlibet -javaagent:/home//byteman/install/lib/byteman.jar=listener:true,boot:/home/adinn/byteman/install/lib/byteman.jar,boot:/home/adinn/byteman/install/sample/lib/byteman-sample.jar,script:/home/adinn/byteman/install/sample/scripts/ThreadMonitor.txt -Djava.net.preferIPv4Stack=true

Let's look at the actual -javaagent argument to understand what is needed to point the agent at the script and the relevant libraries. To make it a bit easier to see what is going on I have added line breaks after the equal sign and commas which separate the different options. In reality the argument needs to be supplied as one long string with no spaces or line breaks.

-javaagent:/home/adinn/byteman/install/lib/byteman.jar=
listener:true,
boot:/home/adinn/byteman/install/lib/byteman.jar,
boot:/home/adinn/byteman/install/sample/lib/byteman-sample.jar,
script:/home/adinn/byteman/install/sample/scripts/ThreadMonitor.txt

Before we look at these options in detail I'll also point out that the java command line included the following property setting

-Dorg.jboss.byteman.quodlibet

This property enables injection into java.lang classes. Normally the agent ignores rules which apply to this package on the grounds that by modifying these classes it will likely shoot itself in the foot changing the JVM functionality it relies on to execute rules. Setting this flag tells it to remove this restriction. There is no great harm in trying this but beware! Get your rules wrong and you will probably see a JVM error such as a stack overflow.

Ok, warnings aside let's return to the -javaagent argument. The first value following the -javaagent: prefix is the location of the byteman jar. If BYTEMAN_HOME identifies the directory into which the release has been installed then the library is located in $BYTEMAN_HOME/lib/byteman.jar, in this case /home/adinn/byteman/install/lib/byteman.jar.

The = sign following the jar file name is used to separate it from the agent options which configure various aspects of the agent's behaviour. Where more than one option is supplied then they must be separated using commas. The options provided in this case include a script: option. This points the agent at the script file containing rules which trace thread activity. You can provide multiple script: options if you want to inject several sets of rules. For example, you might also want to use the ClassLoadMonitor script to monitor class loading. The agent options list also contains two boot: options which supply jars to be added to the bootstrap classpath (we'll come to this later) and a listener: option which is used to start the agent listener.

The first option is listener:true. This causes the agent to start a listener thread which can be communicated with using the submit.sh script located in the Byteman bin directory. The submit script allows you to manage the rule base at runtime. You can check which rules have been injected, compiled and executed. You can also load and unload rules while the program is running, including loading updated versions of rules to fix errors or patch the rule behaviour. The listener will not be started if listener:false is provided or if the listener option is omitted.

So, if you want to be able to switch tracing on and off you must provide option listener:true. If not then you cannot add or remove any rules and you will be stuck with whatever rules were loaded at boot time. You can, of course, omit the script: option. It's ok to start with a vanilla JVM. If you do this then you can load the rules later when you want to turn tracing on.

Let's take a closer look at the submit script. Running submit.sh with no arguments lists all the currently installed rules:

[adinn@toby trunk]$ $BYTEMAN_HOME/bin/submit.sh
# File /home/adinn/byteman/install/sample/scripts/ThreadMonitor.txt line 66
RULE ThreadMonitor trace start
CLASS java.lang.Thread
METHOD start
HELPER org.jboss.byteman.sample.helper.ThreadMonitorHelper
AT EXIT
IF TRUE
DO traceStart($0)
ENDRULE
Transformed in:
loader: sun.misc.Launcher$AppClassLoader@480457
trigger class: java.lang.Thread
compiled successfully
# File /home/adinn/byteman/install/sample/scripts/ThreadMonitor.txt line 52
RULE ThreadMonitor trace create
CLASS java.lang.Thread
METHOD <init>
HELPER org.jboss.byteman.sample.helper.ThreadMonitorHelper
AT EXIT
IF TRUE
DO traceCreate($0)
ENDRULE
Transformed in:
loader: sun.misc.Launcher$AppClassLoader@480457
trigger class: java.lang.Thread
compiled successfully
# File /home/adinn/byteman/install/sample/scripts/ThreadMonitor.txt line 80
RULE ThreadMonitor trace exit
CLASS java.lang.Thread
METHOD exit
HELPER org.jboss.byteman.sample.helper.ThreadMonitorHelper
AT ENTRY
IF TRUE
DO traceExit($0)
ENDRULE
Transformed in:
loader: sun.misc.Launcher$AppClassLoader@480457
trigger class: java.lang.Thread
compiled successfully

The output shows each of the 3 rules which were in the original script and shows that they have been injected into class java.lang.Thread loaded by the bootstrap class loader (it actually says sun.misc.Launcher$AppClassLoader@480457 but no other classloader will load this class). The last line of output for each rule indicates that the rule was parsed and type-checked successfully.

Running the submit script with the -u flag causes the rules to be unloaded:

[adinn@toby trunk]$ $BYTEMAN_HOME/bin/submit.sh -u \
$BYTEMAN_HOME/sample/scripts/ThreadMonitor.txt
uninstall RULE ThreadMonitor trace create
uninstall RULE ThreadMonitor trace start
uninstall RULE ThreadMonitor trace exit
[adinn@toby trunk]$ $BYTEMAN_HOME/bin/submit.sh
no rules installed

The agent responds to the uninstall request by removing any rules defined in the supplied scripts (n.b. if submit.sh -u is run with no script arguments it removes all rules). The agent recompiles the methods of any affected classes to remove the injected trigger code. In this case the rules only apply to class Thread so only one class needs to be recompiled. When submit completes the Thread methods will have reverted to operating as they would do normally and no more trace will be generated. So, tracing has been switched off.

The rules can be reinstated by resubmitting the script:

[adinn@toby trunk]$ $BYTEMAN_HOME/bin/submit.sh \
$BYTEMAN_HOME/sample/scripts/ThreadMonitor.txt
install rule ThreadMonitor trace create
install rule ThreadMonitor trace start
install rule ThreadMonitor trace exit

The agent handles an install request by identifying all classes to which the rules apply and recompiling them, injecting the newly uploaded trigger code. In this case the only class affected is Thread so its methods are recompiled inserting trigger code for the tracing rules once again.

If an uploaded rule has the same name as one that is currently loaded then the old trigger code is removed and new code injected. So, the submit script can be used to modify injected rules on the fly. If your rule shows something interesting and you want to see more details then just redefine and upload your trace rules to print out more details.

In other cases uploaded rules may not match any currently loaded classes. However, they are still added to the agent's rule base. The rule code will be injected when a class is loaded to which the rule applies.

Ok, finally, let's return to the boot: options provided as part of the -javaagent argument. The options are used to ensure that the two jar files are available when the trigger/rule code are type-checked and compiled.

The first jar to consider is the sample library /home/adinn/byteman/install/sample/lib/byteman-sample.jar which contains the implementation of the helper classes StackTraceHelper and ThreadMonitorHelper. When the rules are injected these classes need to be available in the JVM classpath or else the rule code will fail to typecheck and compile.

Normally, it would be sufficient to place the samples library jar in the runtime classpath provided on the java command line. Once this is done it does not usually matter what classloader the trigger class is loaded by since the system classloader is normally a parent for it. So, when type checking the injected rule the helper class will be found by delegation. As an alternative, the agent option sys: can be used to append the jar file to the system classpath. This also ensures the helper classes will be found by delegation.

The only problem with this is that the rules in the thread monitor script need to be injected into JVM classes. These classes are loaded by the bootstrap loader. Unfortunately, the system classloader is not a parent loader for the bootstrap loader -- in fact, the parent relationship is the other way round. Adding the sample library jar to the bootstrap classpath means that it is visible when injecting into JVM classes. Hence, we need to supply the boot: option for this jar.

If you didn't install your helper jar at boot time then you could always use submit.sh to install it at runtime. As long as you have started the listener you can call submit -s my.jar or submit -b my.jar to add a jar to, respectively, the system classpath or bootstrap classpath. Obviously, you need to do this before you load any rules which refer to the helper classes. Unfortunately, there is no way to remove jar files once they have been added in this way.

The other jar supplied using the boot: option is the byteman jar itself. The reasoning here is much the same -- the agent classes need to be visible to bootstrap classes. Normally, when the agent jar is installed its classes get loaded by the system classloader. However, in this case we want to inject a trigger call into a JVM class. If the agent classes such as Rule etc are loaded by the system classloader then they will not be visible from classes such as Thread. So, we also need to supply the boot: option for the byteman jar.

Note that it is not possible to add the byteman jar to the bootstrap classpath using submit. By the time the listener is up and running some agent classes will already have been loaded into the system classloader. Trying to install the byteman jar into the bootstrap classpath at this point will send you straight to classloader hell.

So, let's recap. If you want to start the agent so you can load and unload scripts at runtime and inject into any class, including JVM classes, you need to set

export BJAR=$BYTEMAN_HOME/lib/byteman.jar

and then run your java command with arguments

-javaagent:$BJAR=listener:true,boot:$BJAR

-Dorg.jboss.byteman.quodlibet

When you want to start tracing (firsttime only) you install your helper jar using

$BYTEMAN_HOME/bin/submit.sh \
-b $BYTEMAN_HOME/sample/lib/byteman-sample.jar

You can then load your script using command

$BYTEMAN_HOME/bin/submit.sh \
$BYTEMAN_HOME/sample/scripts/ThreadMonitor.txt

To check that your rules have been injected and compiled use command

$BYTEMAN_HOME/bin/submit.sh

To stop tracing you unload the script using

$BYTEMAN_HOME/bin/submit.sh -u \
$BYTEMAN_HOME/sample/scripts/ThreadMonitor.txt