Instrumentation using AspectJ

Many of us start writing the code without worrying about how performant it will be? Once the program started working, we will be making changes like adding logs, timing statements to check the performance.
I too used to do the same before i came across AspectJ (Even though it was there since 2003, i came across it very recently).
AspectJ is available as

1. Eclipse plugin
2. Standalone compiler 

Let me show you an example on how to check the execution time of a method in a Test program.

Aspect

It's pretty simple. It is more or less a Java Class with special keywords. The following is the aspect which will be called before and after a method call

mport org.aspectj.lang.Signature;

public aspect MethodExeuctionTime {
    pointcut traceMethods() : (((execution(* com.instrument.test.CommonProcessor.test(..)))
            || (execution(* com.test.InstrumentProcessor.process1(..)))
            || (execution(* com.instrument.test.CommonProcessor.test(int)))
            || (execution(* com.test.InstrumentProcessor.process3(..))))
         && !cflow(within(MethodExeuctionTime)));

    before(): traceMethods(){
        Signature sig = thisJoinPointStaticPart.getSignature();
        String name = Thread.currentThread().getName();
        TimingUtils.addStart(sig.getName(), sig.getDeclaringTypeName(), System.currentTimeMillis(),name );
    }

    after(): traceMethods(){
        Signature sig = thisJoinPointStaticPart.getSignature();
        String name = Thread.currentThread().getName();
        TimingUtils.addEnd(sig.getName(), sig.getDeclaringTypeName(), System.currentTimeMillis(), name);
    }
}

Explanation:

• pointcut is a rule where the aspect to be implemented. Syntax is pointcut <method-name> : {conditions to execute}
• Conditions - Here in the example says during the execution of methods provided.
• Conditions can be specified using wild chars like (*).  Logical expressions (|| or &&).
• Finally defined the actual method. Here we see that there are two definitions of method traceMethods (In fact they are not definitions). Which says what code to execute before the method call and after method call respectively.

TimingRecord.java and TimingUtils.java are as follows

public class TimingRecord {
    private long startTime;
    private long endTime;
    private String methodName;
    private String packageName;
    private String threadName;

    public TimingRecord(long startTime, String methodName, String packageName, String threadName) {
        this.startTime = startTime;
        this.methodName = methodName;
        this.packageName = packageName;
        this.threadName = threadName;
    }
    //getters and setters
}

import java.util.HashMap;
import java.util.Map;
import java.util.Stack;

public class TimingUtils {

    private static Map map = new HashMap();

    public static void addStart(String methodName, String type, long time, String threadName){
        String key = threadName+type+methodName;
        TimingRecord record = new TimingRecord(time, methodName, type, threadName);
        Stack stack = (Stack) map.get(key);
        if(stack == null)
            stack = new Stack();
        stack.push(record);
        map.put(key, stack);
    }

    public static void addEnd(String methodName,String type, long time, String threadName){
        String key = threadName+type+methodName;
        Stack stack = (Stack) map.get(key);
        if(stack == null || stack.size() == 0)
            return;

        TimingRecord e = (TimingRecord) stack.pop();
        if(e != null)
        {
            long millis = time - e.getStartTime();
            System.out.println("Time Taken to Execute : Type : "+type+" Thread: "+threadName+" Method : "+methodName + " Time : "+ millis +" ms.");
        }
        map.put(key, stack);
    }
}

How to Compile

Now to compile this, set ajc in your PATH and aspectjrt.jar in CLASSPATH and run the following command

• ajc * -d ../classes -outxml -outjar aspectj.jar

This creates a jar named aspectj.jar with an xml file ajc-aop.xml inside it which tells whats the aspect name to be injected.

How to Run

• Add the following lines to the command line of your program execution.
• -javaagent:<path-to-aspectjlib>/aspectjweaver.jar
• -cp <class-path>:<path-to-project>/aspectj.jar

Sample Program

Look at the following example program

package com.test;

import com.instrument.test.CommonProcessor;

public class InstrumentTest extends Thread
{
    public static void main(String[] args)
    {
        InstrumentTest i1 = new InstrumentTest();
        i1.setName("I1");
        InstrumentTest i2 = new InstrumentTest();
        i2.setName("I2");
        InstrumentTest i3 = new InstrumentTest();
        i3.setName("I3");
        i1.start();
        i2.start();
        i3.start();
    }

    public void run()
    {
        try {
            System.out.println("Started Processing : "+getName());
            InstrumentProcessor p1 = new InstrumentProcessor();
            p1.process1();
            p1.process2();
            p1.process3();
            System.out.println("Completed Processing : "+getName());
        } catch(Exception e) {
            
        }
    }
}

package com.test;

public class InstrumentProcessor
{
    public void process1() throws Exception {
        Thread.sleep(3000);
    }
    
    public void process2() throws Exception {
        Thread.sleep(4000);
    }
    
    public void process3() throws Exception {
        Thread.sleep(5000);
    }
}

Run the program 

Without instrumentation 

• The log will be similar to

Started Processing : I1
Started Processing : I3
Started Processing : I2
Completed Processing : I2
Completed Processing : I1
Completed Processing : I3

With Instrumentation 

• Add the parameters mentioned above (-javaagent and aspectjrt.jar,aspectj.jar to class path). 
• The log will be

Started Processing : I1
Started Processing : I3
Started Processing : I2
Time Taken to Execute : Type : com.test.InstrumentProcessor Thread: I3 Method : process1 Time : 3006 ms.
Time Taken to Execute : Type : com.test.InstrumentProcessor Thread: I2 Method : process1 Time : 3006 ms.
Time Taken to Execute : Type : com.test.InstrumentProcessor Thread: I1 Method : process1 Time : 3006 ms.
Time Taken to Execute : Type : com.test.InstrumentProcessor Thread: I1 Method : process3 Time : 5001 ms.
Time Taken to Execute : Type : com.test.InstrumentProcessor Thread: I2 Method : process3 Time : 5001 ms.
Completed Processing : I2
Time Taken to Execute : Type : com.test.InstrumentProcessor Thread: I3 Method : process3 Time : 5003 ms.
Completed Processing : I1
Completed Processing : I3

There are so many other cases you can instrument using AspectJ. This is just one of them.

Happy Learning!!!!!