Tracing Java Method Execution with AspectJ

ApectJ is a project to bring aspect oriented programming to Java.  Sidestepping the whole issue around whether or not aspect-oriented programming is a good idea; it can be used to insert code at points you define and is a very useful tool for dynamic program analysis.

Some terminology needs explaining here before we go further.  AspectJ defines a point in the source to stop execution and pass it to your code as a “Pointcut”, the actual code executed on this pause is termed “advice”.  Although I use the word “pause” it’s not strictly correct; AspectJ “weaves” the advice code for matching pointcuts at compile time. Additionally (and perhaps most significantly) AspectJ can weave on class load time (“Load Time Weaving”), this is what we’ll be using.

So we have a way of inserting code in places in an existing code base, what can we do with it?  A lot of horrible things (playing around with returned values and parameters to name a few); but for now we’ll stick to what we want to do, tracing method calls.

The most obvious way to instrument a program is to insert calls to some logging library at the top of every method.  Although this works it takes a lot of time, either manually logging everything or figuring out how to use a regex/parser to do it for you.  With AspectJ we can simply weave code that logs the current method at every method execution point.

So how do we do that?  First we need to get AspectJ working; Eclipse will do that for you, alternatively you can do everything from the command line (assuming you have AspectJ installed, including the ajc command on your PATH).

We’ll define an Aspect that defines a pointcut on every method execution, as well as some advice to run when they turn up when the code is executed.

package aspects;

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

import org.aspectj.lang.Signature;

aspect Trace{


	pointcut traceMethods() : (execution(* *(..))&& !cflow(within(Trace)));

	before(): traceMethods(){
		Signature sig = thisJoinPointStaticPart.getSignature();
		String line =""+ thisJoinPointStaticPart.getSourceLocation().getLine();
		String sourceName = thisJoinPointStaticPart.getSourceLocation().getWithinType().getCanonicalName();
		Logger.getLogger("Tracing").log(
                Level.INFO, 
                "Call from "
                	+  sourceName
                    +" line " +
                    line
                    +" to " +sig.getDeclaringTypeName() + "." + sig.getName()
		);
	}

}

So what exactly does this do? Firstly, the pointcut traceMethods() defines a new pointcut called traceMethods. This pointcut matches execution of every method in every class, as long as the control flow isn’t in the current class (Trace). The latter constraint is to stop an infinite loop occurring.

The before(): part of the class defines advice. This is the code that gets inserted just before the execution of the method. Advice can also be given after a pointcut is hit (using the after keyword instead). Our “advice” doesn’t modify execution flow, it just logs some information about the state of the program when the pointcut was hit, but it could quite easily start modifying control flow.

Save this file as Trace.java and compile it using: ajc -outxml -outjar aspects.jar Trace.java.

This compiles the aspect and puts it into a jar ready for use. The -outxml parameter will cause ajc to automatically generate an aop.xml file and save it in the jar’s META-INF directory. The load time weaving agent will read this to determine which aspects to weave with the classes it loads. The aop.xml file can do more than that, it can be used to set namespaces to ignore when weaving (such as java.*) to avoid mucking with the control flow of libraries.

So now we have our aspects.jar how do we use it? The AspectJ weaving agent must be available somewhere on the filesystem (aspectjweaver.jar) and your aspect.jar (and the target application) must be on the classpath.

Once that’s sorted to trace the application, use

java -javaagent:<path to aspectjweaver.jar> -cp <path to aspects.jar>:<path to target jar/folder> <name of main class to run>

Hopefully that will run and you should see a large amount of console output:

INFO: Call from main.RunFile line 206 to main.RunFile.main
Mar 31, 2011 2:52:53 PM aspects.Trace ajc$before$aspects_Trace$1$b314f86e
INFO: Call from main.RunFile line 186 to main.RunFile.runList
Mar 31, 2011 2:52:53 PM main.RunFile main
INFO: Starting clustering of 0 files
Mar 31, 2011 2:52:53 PM aspects.Trace ajc$before$aspects_Trace$1$b314f86e
INFO: Call from main.ExperimentRunner line 59 to main.ExperimentRunner.runExperiments


AspectJ lets you do far more than this, it’s an understatement to say this is all it can be used for. Using LTW does make for some interesting possibilities, one obvious use would be monkey patching existing projects to fix bugs where source isn’t available (and the license permits it, of course).

AspectJ is an interesting piece of work; the official project page has far more resources on the types of pointcuts you can define and the more nitty-gritty details of making it mess with the traced program.