This is not a walk-thru. This is just an example AspectJ class.

Note: For logging, the log singleton which I previously posted is used, but of course you can hook this up to your own logging methods or just print to the console.

This class is intended to log when a method executes and when a method ends and include the time it took for a method to execute in nanoseconds. Methods inside methods are tabbed. This is an enhancement to this post: AOP – Logging all method calls and executions

package mainExample;

import java.util.Stack;
import org.aspectj.lang.JoinPoint;

public aspect AspectLogMethodExecution
{
	private int tabCount = 0;
	private Stack _StartTimeStack = new Stack();

	pointcut AnyMethod() : (call(* *.*(..)) || execution(* *.*(..)))
						&& !within(AspectLogMethodExecution)
						&& !within(Log);

	before() : AnyMethod()
	{
		PrintMethod(thisJoinPointStaticPart);
		tabCount++;
		_StartTimeStack.add(System.nanoTime());
	}

	after() : AnyMethod()
	{
		Long methodExecutionTime = EvaluateExecutionTime();
		tabCount--;
		PrintMethod(thisJoinPointStaticPart, methodExecutionTime);
	}

	private Long EvaluateExecutionTime()
	{
		Long methodExecutionTime = System.nanoTime() - _StartTimeStack.pop();
		return methodExecutionTime;
	}

	private void PrintMethod(JoinPoint.StaticPart inPart)
	{
		Log.WriteLine(GetTabs() + inPart);
	}

	private void PrintMethod(JoinPoint.StaticPart inPart, long inExecutionTime)
	{
		Log.WriteLine(GetTabs() + inPart + " Execution Time: "
				+ inExecutionTime + " nanoseconds");
	}

	private String GetTabs()
	{
		String tabs = "";
		for (int i = 0; i < tabCount; i++)
		{
			tabs += "\t";
		}
		return tabs;
	}
}

So if you have a simple Hello, World app, this is the log output.

execution(void mainExample.Main.main(String[]))
	call(void java.io.PrintStream.println(String))
	call(void java.io.PrintStream.println(String)) Execution Time: 112063 nanoseconds
execution(void mainExample.Main.main(String[])) Execution Time: 904636 nanoseconds

I ran it multiple times and the executions times were sporadic. I remember reading somewhere that System.nanoTime() in java was not extremely accurate, but it is accurate enough for this example.

 
Return to Aspected Oriented Programming – Examples