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.

11 comments:

  1. Hi Andrew,
    Nice to see a blog just for byteman related
    discussions.
    The ^ functionality is powerful, awesome.
    By the way, your README for release 1.2.0.1 says 1.1.1 :)
    cheers,
    jay

    ReplyDelete
  2. Thanks for the tip and the ever-positive feedback.

    regards,


    Andrew Dinn
    -----------

    ReplyDelete
  3. Hi Andrew,

    I have a problem for which I would like your advice.
    Here is a harmless looking class that has a major and "difficult-to-test" problem :
    public class AppServerEnv {

    private boolean _isProduction;
    // solution-1
    //private final boolean _isProduction;

    private static AppServerEnv _instance;

    private AppServerEnv( ) {
    _isProduction = Boolean.getBoolean( "production" );
    }

    public static AppServerEnv getInstance( ) {
    // solution-1
    //public synchronized static AppServerEnv getInstance( ) {
    if( _instance == null )
    _instance = new AppServerEnv( );
    return _instance;
    }

    public boolean isProduction( ) {
    return _isProduction;
    }

    }

    Let's have 2 threads thread-1 and thread-2.
    Thread-1 is in getInstance(), finds _instance==null and starts to execute the following line :

    _instance = new AppServerEnv( );

    Now, _instance could get updated "before" the constructor.
    Thread-2 comes along, checks _instance != null, picks
    up the _instance and calls isProduction() to get an old value of the boolean _isProduction, since Thread-1 has not yet completed the constructor execution.
    The problem here is to do with the actual
    execution sequence of the "new..." call on the
    target CPU. Since byteman uses the bytecode to
    simulate the interleaving of threads, I am
    guessing that it is "impossible" to simulate
    this interleaving using the byteman library.
    Or am I wrong ?
    Any suggestions, tips, assistance will be much
    appreciated.

    cheers,
    jay

    ReplyDelete
  4. Hi Jay,

    There is indeed a danger with your unsynchronized static that thread 2 may see an uninitialised version of the AppServerEnv object. That is to do with the way the memory system works on multi-core or multi-processor systems. From the point of view of Thread 1 the constructor will always be executed before assigning the static field _instance. However, in the absence of a synchronization it is possible on certain hardware architectures that Thread 2 may see the assignment to _instance but not see the assignment to field _isProduction of that instance. In other words the writes may happen out of order when viewed form a parallel thread. A memory barrier instruction of the appropriate type must be executed by both the writer thread and the reader thread in order to ensure that writes are published before they are read. A Java compiler will only generate these instructions when the source code doing the write and/or read is synchronized.

    Now, there is no way you can manifest this behaviour using Byteman because Byteman can only introduce orderings between threads by introducing synchronization operations. This will ensure that any out of order operations which might be visible to other threads are completed by the writer thread before they can be seen in the reader thread. So, when you reorder things using byteman memory operations will strictly follow source code order before and after the point at which you inject the rule code.

    That said, you can write some Byteman rules to manifest the race condition implicit in this class. Here is what you need:

    RULE setup rendezvous
    CLASS AppServerEnv
    METHOD
    IF TRUE
    DO createRendezvous("AppServerEnv", 2)
    ENDRULE

    RULE enforce rendezvous before write
    CLASS AppServerEnv
    METHOD getInstance()
    AT WRITE _instance
    IF TRUE
    DO traceln("writing _instance in thread " + Thread.currentThread()) rendezvous("AppServerEnv", 2)

    RULE trace create calls
    CLASS AppServerEnv
    METHOD
    AT ENTRY
    IF TRUE
    DO traceln("creating _instance in thread " + Thread.currentThread())
    ENDRULE

    The first rule gets run when the AppServerEnv is loaded and sets up a 2 way rendezvous. The second rule is triggered just before field _instance is written. So, the first thread to enter getInstance() will wat before completing its write, allowing the second thread to also create and write the field. Once both threads are ready to assign the instance they will pass the rendezvous and each one will perform the assignment in turn.

    ReplyDelete
  5. Hi Andrew,

    Thanks once again for your detailed explanation.
    In short, yes, I was afraid you were going to say that :)
    But yes, the race condition is easy to simulate and test. I will use that since I cannot simulate the "old value boolean test"
    using byteman library.
    By the way, your script has some errors. I noticed that when I ran it.
    Here are the errors I noticed :
    1) in rules 1 and 3 the method name is missing
    2) rendezvous call has a 2nd parm., which should not be there.

    I made some corrections and came up with the following script :

    RULE setup rendezvous
    CLASS AppServerEnv
    METHOD "<"init">"()
    IF TRUE
    DO traceln( "creating _instance in thread " + Thread.currentThread() ),
    createRendezvous("AppServerEnv", 2)
    ENDRULE
    #
    RULE enforce rendezvous before write
    CLASS AppServerEnv
    METHOD getInstance()
    AT WRITE _instance
    IF TRUE
    DO traceln( "writing _instance in thread " + Thread.currentThread() ),
    rendezvous("AppServerEnv")
    ENDRULE

    Please note that I had to put " sign in the method name, otherwise my posted comment, in this blog, removes the left/right parantheses and
    everything between.
    Of course, in this case, createRendezvous()
    will be executed for each thread, but only
    the first execution of it will succeed and
    subsequent ones will fail anyway.
    So it does not matter, right ?
    Is this ok ?

    cheers,
    jay

    ReplyDelete
  6. Ah, my apologies for the missing method name. I actually entered the name for the class initialiser which is <clinit>. I forgot to write it using &lt; and &gt; so it got elided as an unknown HTML tag.

    The <clinit> method is preferable to the <init> method because the rule only fires once at class load time. However, there is a drawback with injecting code into this method.

    If you try to submit the rules via the agent listener after the program has started then the clinit rule may not get triggered. If the class has already been loaded when the rules are submitted then the methods will be redefined and recompiled. However, the class static init code is not rerun so the rule code will not get executed. So, <clinit> rules are only recommended for loading via the JVM/agent command line.

    regards,


    Andrew Dinn
    -----------

    ReplyDelete
  7. Hi Andrew,

    Ah, . Ok. Thanks for the information.
    cheers,
    jay

    ReplyDelete
  8. Hi Andrew,

    Tried to output the transformed class using the
    system property -Dorg.jboss.byteman.dump.generated.classes=1 -Dorg.jboss.byteman.dump.generated.classes.directory=c:\\temp\\junk, but byteman did not write out
    anything. In fact, the transformation did not happen at all and the program ran without instrumentation.
    Have I defined the properties ok ? I also tried the value "true" for the system property org.jboss.byteman.dump.generated.classes, but no luck.

    cheers,
    jay

    ReplyDelete
  9. Hi Jay,

    Hmm, I am not sure about what is happening here but the lack of any transformation is perhaps more telling than the lack of dumped files -- if no classes get modified then there is no code to dump. Try switching on trace with -Dorg.jboss.byteman.verbose to see if it is attempting to transform anything. If that fails perhaps you could report this on the Byteman user forum (accessible via ww.org.jboss.byteman) and I will look into it in more detail.

    ReplyDelete
  10. oops, sorry that URL should have read www.jboss.org/byteman -- click on the community tab for the user forum

    ReplyDelete
  11. Hi Andrew,

    Thanks for your prompt reply. Much appreciated :)
    Actually instrumentation happens, but no
    output of classes.
    I have posted the question again in the
    byteman user forum at www.jboss.org/byteman,
    as suggested by you.
    Please have a look there.
    Thanks for looking into it.

    cheers,
    jay

    ReplyDelete