Tuesday 1 December 2009

Byteman 1.2.0 Bytes Deeper Into Your Code

The latest (1.2.0) version of Byteman is now available and it includes some new features which make it easier to specify where you want side effects to be injected to your code. These features are particularly useful for tracing but they are also of great benefit when it comes to using Byteman for its primary purpose which is fault injection testing.

Recap For Newcomers


For those of you who are new to Byteman or who did not see the earlier blog post about Monitoring the JVM using Byteman I'll just recap that Byteman is a bytecode injection tool which can be used to tweak application or JVM runtime code, adding side effects at specific points in any Java method. The injected code is not restricted to performing unintrusive actions like gathering statistics or printing trace output. It can access in scope objects and invoke public methods, changing either the application or the runtime state if it needs to. It can also short circuit the call to the modified method, forcing an immediate return or throwing an exception.

Byteman makes it easy to inject code which traces and verifies program execution and this is often all that is needed to test simple programs. However, in more complex tests the injected code will set up situations which exercise specific code paths by doing things like returning a spurious value, throwing an unexpected exception, inserting a timing delay, suspending one thread until another thread has completed some activity and so on. The most complex tests scenarios require multiple, highly specific interventions to propagate the effect of an initial fault. Byteman provides a simple, clear and expressive rule language based on Java which enables you to perform all these tasks. The programmer's guide is a good place to start if you want to full details of the language and how to use it to script test scenarios.

Back To The Program: A Sample Rule


Ok, so let's get back to those new features in 1.2.0 by introducing an example. I'm mostly going to stick to injecting trace code in the rest of this post but it should be obvious how the same features can be useful when defining rules which inject or propagate faults.

Here's one of the Byteman sample rules taken from the release which traces execution of the JVM Socket code.
RULE Socket trace bind
CLASS ^java.net.Socket
METHOD bind(SocketAddress)
HELPER org.jboss.byteman.sample.helper.StackTraceHelper
AT EXIT
IF TRUE
DO traceStack("*** bind " + $this, 15)
ENDRULE

This rule is attached to CLASS Socket and targets METHOD bind(SocketAddress). It is triggered at EXIT from a call to bind and is fired unconditionally (i.e. the IF condition is TRUE) because we want to trace all calls to bind. The rule employs a HELPER class called StackTraceHelper which is provided in the sample library contained in the release. This helper class implements a method traceStack(String prefix, int depth) which can be called in the body of the rule as a built-in operation (i.e. with no target for the method call). Unsurprisingly, this helper method prints a prefix line and then dumps the stack. The depth argument provides an upper limit on the number of stack frames displayed.

The prefix in this case is constructed by concatenating the String literal "*** bind " with the parameter variable $this. The latter refers to the target instance for the bind call i.e. the socket being bound. The rule type checker identifies that $this is of type Socket, recognises that it is being consumed by a string plus operation where a String value is expected and automatically promotes $this to the correct type by inserting a toString() method invocation into the expression chain.

A helper method is used merely to simplify the rule, in this case wrapping up the code which traverses the stack and dumps details of each stack frame into a single call. The default helper provides, amongst other things, methods which can be used to synchronize independent threads, making it easy to orchestrate quite complex interactions in a multi-threaded application. Using custom helpers is particularly beneficial when scripting complex tests because many rules will perform common operations such as gathering statistics or detecting application-specific conditions and providing simple pre-canned calls keeps the rules clear.

It is perfectly possible to write code directly into the rule condition or action without using helper calls. Rule conditions and actions can call static methods or instance methods of accessible objects. For example, the following rule checks the port to which a socket has been bound and in one specific case prints a message to System.out then throws an exception
RULE Socket emergency!
CLASS ^java.net.Socket
METHOD bind(SocketAddress)
HELPER org.jboss.byteman.sample.helper.StackTraceHelper
AT EXIT
IF $0.getLocalPort() == 999
DO System.out.println("Found the 999 call"),
throw IOException("Call the police!")
ENDRULE

Note that this version must be invoked at EXIT because the call to getLocalPort() will only return the bound port after the call to bind has completed and is about to return.

So What's New In 1.2?


Now, the observant reader will have noticed that there is one small detail of the rule definition which I have not actually referred to yet: the ^ character preceding the class name. This bit of syntax is new with release 1.2.0 and although it comprises only a single character it makes the world of difference to the meaning of the rule.

The previous Byteman release contained a version of the 'Socket trace bind' rule without the ^ prefix and, in certain circumstances, this meant that bind calls were not traced. The problem is that in the Sun JVM there is a class called sun.nio.ch.SocketAdaptor which extends java.net.Socket. This method provides its own overriding implementation of bind(SocketAddress) and the overriding implementation does not make a call to super.bind(SocketAddress). The old version of the rule only gets injected into the bind method of class Socket. That means when a SocketAdaptor was bound the call to bind was not traced.

The ^ annotation means that the rule should apply to any implementation of method bind(SocketAddress) either on class Socket or a subclass which overrides the method. So, when using the Sun JVM the rule gets injected into class Socket and class SocketAdaptor. It also gets injected into abstract class com.sun.net.ssl.internal.ssl.BaseSSLSocketImpl and into any other application specific class which overrides Socket.bind(SocketAddress). So, with this new syntax there is no danger of missing a socket bind on the 999 port.

A Must-Have Override Example


Another example of the value of overriding rules is provided by the following rule taken from the sample scripts.
RULE FinalizeMonitor trace finalize
CLASS ^java.lang.Object
METHOD finalize
HELPER org.jboss.byteman.sample.helper.StackTraceHelper
AT RETURN
IF TRUE
DO traceStack("finalizing " + $0, 1)
ENDRULE

This method traces every call to a finalize method and the ^ annotation ensures that it is injected into every overriding implementation of Object.finalize(). Note that without the ^ annotation the rule is useless because the garbage collector never calls finalize for objects whose class does not override Object.finalize()!

What About Interfaces?


So, that's one half of the extra functionality provided in Byteman 1.2.0, injection down class hierarchies. The other half is to allow injection through interfaces. All the examples so far have talked about injecting code into methods but when it comes to interfaces there are no methods to consider, only signatures. Here's an example taken from another of the sample rules.
  RULE ThreadMonitor trace Runnable.run
INTERFACE java.lang.Runnable
METHOD run()
HELPER org.jboss.byteman.sample.helper.ThreadMonitorHelper
AT ENTRY
IF TRUE
DO traceRun($0)
ENDRULE

This rule is attached to a method of interface Runnable and is triggered by a call to the interface method run(). It uses a subclass of StackTraceHelper called ThreadMonitorHelper as its helper class. The built-in method traceRun prints the Runnable and its type and then prints details of the caller method which invoked run().

But what exactly does it mean to say "triggered by a call to the interface method run()"? Byteman identifies all classes which implement interface Runnable and injects the rule into the implementation of run() on these classes. So, for example, it will inject the rule into java.lang.Thread.run(), java.util.TimerThread.run() and so on.

Orthogonal? Composable?


Now, this is good because it means we don't have to write a rule for every class which implements Runnable. However, it is not quite enough to guarantee that every call to run() will be traced. For example, an application class which extends java.lang.Thread and provides its own implementation of run() will not be caught by this rule because it does not directly implement Runnable. The same applies to anonymous classes created to wrap an inline code block following a new expression such as
  Thread myWorker = new Thread() {
public void run() { doBackGroundWork(); }
};
myWorker.start();

The anonymous class associated with myWorker does implement a run() method, overriding the implementation in Thread, but the class does not declare Runnable in its list of implemented classes. So, Byteman will not inject trace code into this overriding implementation and, hence, any call to myWorker.run() will not be traced.

The solution to this problem is simple. Just prefix the interface with the ^ annotation and injection is performed through the interface and down the resulting class hierarchies. The two new injection modes are orthogonal and composable.

Let's See That In Action


RULE ThreadMonitor trace Runnable.run
INTERFACE ^java.lang.Runnable
METHOD run()
HELPER org.jboss.byteman.sample.helper.ThreadMonitorHelper
AT ENTRY
IF TRUE
DO traceRun($0)
ENDRULE
This version of the rule injects the rule code through the interface into implementing classes and down their subclass hierarchies into overriding implementations. It prints details of every call to and caller of Runnable.run() either internal to the JVM runtime or in application code. Here's a sample of the output when this rule is used to trace execution of the latest JBoss Application Server startup.
 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.transform.all -javaagent:/home/adinn/jboss/byteman/trunk/install/lib/byteman.jar=listener:true,script:TraceRun.txt,boot:/home/adinn/jboss/byteman/trunk/install/lib/byteman.jar,boot:/home/adinn/jboss/byteman/trunk/install/sample/lib/byteman-sample.jar -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
=========================================================================
Listening for transport dt_socket at address: 5005
*** Thread run main java.lang.Thread
from VM runtime
12:52:04,447 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 run Thread-3 java.lang.Thread
from VM runtime
*** Runnable run org.jboss.bootstrap.impl.base.server.AbstractServer$StartServerTask@1aecc3a org.jboss.bootstrap.impl.base.server.AbstractServer.StartServerTask
from java.lang.Thread.run at Thread.java:619
12:52:04,462 INFO [AbstractServer] Starting: JBoss Server[6.0.0.SNAPSHOT (build: SVNTag=JBoss_6.0.0-SNAPSHOT date=r93729)]
12:52:05,881 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 run Timer-0 java.util.TimerThread
from VM runtime
*** Runnable run org.jboss.util.TimedCachePolicy$ResolutionTimer@1415727 org.jboss.util.TimedCachePolicy.ResolutionTimer
from java.util.TimerThread.mainLoop at Timer.java:512
*** Runnable run org.jboss.util.TimedCachePolicy@c0fc8e org.jboss.util.TimedCachePolicy
from org.jboss.util.TimedCachePolicy$ResolutionTimer.run at TimedCachePolicy.java:483
12:52:07,243 INFO [VFSCacheFactory] Initializing VFSCache [org.jboss.virtual.plugins.cache.CombinedVFSCache]
12:52:07,247 INFO [VFSCacheFactory] Using VFSCache [CombinedVFSCache[real-cache: null]]
12:52:07,839 INFO [CopyMechanism] VFS temp dir: /home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/server/default/tmp
12:52:07,866 INFO [ZipEntryContext] VFS force nested jars copy-mode is enabled.
*** Thread run ZipFile Lock Reaper java.util.TimerThread
from VM runtime
*** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask
from java.util.TimerThread.mainLoop at Timer.java:512
*** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask
from java.util.TimerThread.mainLoop at Timer.java:512
12:52:10,964 INFO [ServerInfo] Java version: 1.6.0_14,Sun Microsystems Inc.
12:52:10,964 INFO [ServerInfo] Java Runtime: Java(TM) SE Runtime Environment (build 1.6.0_14-b08)
12:52:10,964 INFO [ServerInfo] Java VM: Java HotSpot(TM) Server VM 14.0-b16,Sun Microsystems Inc.
12:52:10,964 INFO [ServerInfo] OS-System: Linux 2.6.30.9-99.fc11.i686.PAE,i386
12:52:10,965 INFO [ServerInfo] VM arguments: -Dprogram.name=run.sh -Xms600M -Xmx600M -XX:MaxPermSize=128m -Xdebug -Xnoagent -Djava.compiler=NONE -Xrunjdwp:transport=dt_socket,server=y,suspend=n,address=5005 -Dorg.jboss.byteman.transform.all -javaagent:/home/adinn/jboss/byteman/trunk/install/lib/byteman.jar=listener:true,script:TraceRun.txt,boot:/home/adinn/jboss/byteman/trunk/install/lib/byteman.jar,boot:/home/adinn/jboss/byteman/trunk/install/sample/lib/byteman-sample.jar -Djava.net.preferIPv4Stack=true -Djava.endorsed.dirs=/home/adinn/jboss/jbossas/trunk/build/output/jboss-6.0.0-SNAPSHOT/lib/endorsed
*** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask
from java.util.TimerThread.mainLoop at Timer.java:512
12:52:11,041 INFO [JMXKernel] Legacy JMX core initialized
*** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask
from java.util.TimerThread.mainLoop at Timer.java:512
. . .
*** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask
from java.util.TimerThread.mainLoop at Timer.java:512
12:52:28,684 INFO [AbstractServerConfig] JBoss Web Services - Native Server
12:52:28,684 INFO [AbstractServerConfig] 3.2.0.GA
*** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask
from java.util.TimerThread.mainLoop at Timer.java:512
*** Thread run SubscriptionWatchDog java.lang.Thread
from VM runtime
*** Runnable run org.jboss.ws.extensions.eventing.mgmt.SubscriptionManager$WatchDog@6b9547 org.jboss.ws.extensions.eventing.mgmt.SubscriptionManager.WatchDog
from java.lang.Thread.run at Thread.java:619
*** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask
from java.util.TimerThread.mainLoop at Timer.java:512
. . .
*** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask
from java.util.TimerThread.mainLoop at Timer.java:512
*** Thread run RMI TCP Accept-1090 java.lang.Thread
from VM runtime
*** Runnable run sun.rmi.transport.tcp.TCPTransport$AcceptLoop@7598d7 sun.rmi.transport.tcp.TCPTransport.AcceptLoop
from java.lang.Thread.run at Thread.java:619
*** Thread run RMI TCP Accept-0 java.lang.Thread
from VM runtime
*** Runnable run sun.rmi.transport.tcp.TCPTransport$AcceptLoop@19de1ba sun.rmi.transport.tcp.TCPTransport.AcceptLoop
from java.lang.Thread.run at Thread.java:619
*** Thread run RMI Reaper java.lang.Thread
from VM runtime
*** Runnable run sun.rmi.transport.ObjectTable$Reaper@185576 sun.rmi.transport.ObjectTable.Reaper
from java.lang.Thread.run at Thread.java:619
*** Thread run GC Daemon sun.misc.GC.Daemon
from VM runtime
*** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask
from java.util.TimerThread.mainLoop at Timer.java:512
*** Thread run RMI TCP Connection(idle) java.lang.Thread
from VM runtime
*** Runnable run java.util.concurrent.ThreadPoolExecutor$Worker@132e9d5 java.util.concurrent.ThreadPoolExecutor.Worker
from java.lang.Thread.run at Thread.java:619
*** Runnable run sun.rmi.transport.tcp.TCPTransport$ConnectionHandler@1231023 sun.rmi.transport.tcp.TCPTransport.ConnectionHandler
from java.util.concurrent.ThreadPoolExecutor$Worker.runTask at ThreadPoolExecutor.java:886
*** Thread run RMI Scheduler(0) java.lang.Thread
from VM runtime
*** Runnable run java.util.concurrent.ThreadPoolExecutor$Worker@701c57 java.util.concurrent.ThreadPoolExecutor.Worker
from java.lang.Thread.run at Thread.java:619
*** Thread run RMI RenewClean-[127.0.0.1:47945] java.lang.Thread
from VM runtime
*** Runnable run sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread@1e88ea sun.rmi.transport.DGCClient.EndpointEntry.RenewCleanThread
from java.lang.Thread.run at Thread.java:619
*** Thread run RMI TCP Connection(idle) java.lang.Thread
from VM runtime
*** Runnable run java.util.concurrent.ThreadPoolExecutor$Worker@1c35be0 java.util.concurrent.ThreadPoolExecutor.Worker
from java.lang.Thread.run at Thread.java:619
*** Runnable run sun.rmi.transport.tcp.TCPTransport$ConnectionHandler@9ba7c9 sun.rmi.transport.tcp.TCPTransport.ConnectionHandler
from java.util.concurrent.ThreadPoolExecutor$Worker.runTask at ThreadPoolExecutor.java:886
*** Runnable run sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread@1e88ea sun.rmi.transport.DGCClient.EndpointEntry.RenewCleanThread
from java.lang.Thread.run at Thread.java:619
12:52:57,324 INFO [JMXConnectorServerService] JMX Connector server: service:jmx:rmi://127.0.0.1/jndi/rmi://127.0.0.1:1090/jmxconnector
*** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask
from java.util.TimerThread.mainLoop at Timer.java:512
*** Thread run ServerSocketRefresh org.jboss.remoting.transport.socket.SocketServerInvoker.ServerSocketRefresh
from VM runtime
*** Thread run AcceptorThread[ServerSocket[addr=/127.0.0.1,port=0,localport=4457]] org.jboss.remoting.transport.socket.SocketServerInvoker.AcceptThread
from VM runtime
*** Thread run secondaryServerSocketThread[0] org.jboss.remoting.transport.bisocket.BisocketServerInvoker.SecondaryServerSocketThread
from VM runtime
*** Thread run ServerSocketRefresh org.jboss.remoting.transport.socket.SocketServerInvoker.ServerSocketRefresh
from VM runtime
*** Thread run AcceptorThread[ServerSocket[addr=/127.0.0.1,port=0,localport=3873]] org.jboss.remoting.transport.socket.SocketServerInvoker.AcceptThread
from VM runtime
*** Runnable run org.jboss.virtual.plugins.context.zip.ZipFileLockReaper$ReaperTimerTask@10a519 org.jboss.virtual.plugins.context.zip.ZipFileLockReaper.ReaperTimerTask
from java.util.TimerThread.mainLoop at Timer.java:512
*** Thread run HDScanner java.lang.Thread
from VM runtime
*** Runnable run java.util.concurrent.ThreadPoolExecutor$Worker@1d64598 java.util.concurrent.ThreadPoolExecutor.Worker
from java.lang.Thread.run at Thread.java:619
*** Runnable run sun.rmi.transport.tcp.TCPTransport$ConnectionHandler@9ba7c9 sun.rmi.transport.tcp.TCPTransport.ConnectionHandler
from java.util.concurrent.ThreadPoolExecutor$Worker.runTask at ThreadPoolExecutor.java:886
Where the Runnable is an instance of Thread the helper code prints the thread name and class. For non-threads it prints the Runnable instance and its class then details of the caller method. Notice that all the run calls associated with threads have no caller frame. This is because the thread stack is set up by the JVM with the run method as its entry point.

Most of the non-Thread Runnables are executed as the target of a dedicated thread and in these cases the call to run is made from Thread.run(). There are a few examples where the run method is invoked by pool threads, for example the last traced call shows a worker from the concurrent thread pool package being used to execute a Runnable which handles a TCP connection. In this case the call to run is made from the worker's execute method.

Friday 23 October 2009

Cross Posting - Now that Byteman has its own Blog

It's great to see that Byteman has its own blog!

Here's a cross-link to a post that I wrote last week - it's a 'helloworld' style introduction to Byteman:

http://java.dzone.com/news/fault-injection-testing-first?mz=3006-jboss

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.transform.all -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.transform.all -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.transform.all
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