As I have mentioned previously, there are several utilities that I often find myself reusing when I join a new project. One of these utilities is the Logging or Tracing Aspect that I have previously discussed while the other is an aspect that facilitates a rudimentary profiling of the application code.

I first got the idea for such a profiling aspect from the Spring Framework user guide which presents a basic implementation in the Spring AOP section. I subsequently observed a more sophisticated implementation developed by Jerry Kiely, who I occasionally have the pleasure of working with.

In what follows, I will present an implementation of a profiling aspect and explain how this can be utilised using Spring and AspectJ Load Time Weaving.

Task and Task Timer Implementation

The profiling aspect will record the start time and end time of each method invocation thus allowing more valuable statistics to be derived at a later point in time. To make this functionality reusable, we will develop more abstract TaskTimer and Task implementations.

The Task represents any action for which we require timing metrics and records the task name, start time and end time.

package net.thoughtforge.task;

public class Task {

  private Long endTime;

  private String name;

  private Long startTime;

  public Task(String name, Long startTime) {
    this.name = name;
    this.startTime = startTime;
  }

  public long getDuration() {
    return endTime - startTime;
  }

  public Long getEndTime() {
    return endTime;
  }

  public void setEndTime(Long endTime) {
    this.endTime = endTime;
  }

  public String getName() {
    return name;
  }

  public Long getStartTime() {
    return startTime;
  }
}

The TaskTimer provides a simple stack based timer implementation that allows one to start a named task, stop a task and obtain a list of all completed tasks. When a named task is started, it is pushed onto the stack and when a task is stopped, it is popped off the stack and the end time is set. The task is then added to a list of completed tasks for futher analysis at a later point in time.

package net.thoughtforge.task;

import java.util.ArrayList;
import java.util.List;
import java.util.Stack;

public class TaskTimer {

  private List completedTasks = new ArrayList();

  private Long endTime;

  private String id;

  private Long startTime;

  private Stack taskStack = new Stack();

  public TaskTimer(String id) {
    this.id = id;
  }

  public long getTaskCount() {
    return taskStack.size();
  }

  public long getTotalDuration() {
    return endTime - startTime;
  }

  public String printSummary() {
    StringBuffer summary = new StringBuffer(shortSummary());
    summary.append('\n');

    TaskSummaryVisitor taskSummaryVisitor = new TaskSummaryVisitor(getTotalDuration());
    for (Task task: completedTasks) {
      taskSummaryVisitor.visit(task);
    }

    summary.append(taskSummaryVisitor.printTaskSummaries());

    return summary.toString();
  }

  public String shortSummary() {
    return "TaskTimer '" + this.id + "': running time (millis) = " + getTotalDuration();
  }

  public void start(String name) {
    Long startTime = System.currentTimeMillis();

    if (taskStack.isEmpty()) {
      this.startTime = startTime;
    }

    taskStack.push(new Task(name, startTime));
  }

  public void stop() {
    Long endTime = System.currentTimeMillis();

    Task currentTask = taskStack.pop();
    currentTask.setEndTime(endTime);

    if (taskStack.isEmpty()) {
      this.endTime = endTime;
    }

    completedTasks.add(currentTask);
  }
}

The TaskTimer is not an exhaustive implementation (no checks for end of stack etc.) so if you intend to reuse this you should certainly adapt it further.

I notice a JIRA issue requesting that Spring add similar functionaliy to the StopWatch class.

The Profiling Aspect

As with the Logging Aspect, the Profiling Aspect uses the @Aspect approach to defining the aspect, advice and pointcuts.

The first thing you will notice is a ThreadLocal reference to a TaskTimer. This ensures the method profile metrics from different threads are not interleaved. It is more that likely that one will want to look at profiling information from a single thread at a time.

The aspect contains a single piece of around advice that creates a task name, starts the task timer, invokes the method and stops the task timer. This is fairly trivial and the only point of interest to draw your attention to is the point where the profiling metrics are output to the logging system.

Effectively, on completion of the method that initiates the profiling, the profiling metrics will be output to the logging system. If you consider a Servlet based application you could imagine the profiling beginning on the Servlet service method, and the profiling information being logged on the completion of the service method.

package net.thoughtforge.aspect;

import net.thoughtforge.task.TaskTimer;

import org.apache.commons.logging.LogFactory;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;

@Aspect
public abstract class ProfilingAspect {

  private ProfilerThreadLocal profilerThreadLocal = new ProfilerThreadLocal();

  @Pointcut
  public abstract void profilingPointcut();

  @Around("profilingPointcut()")
  public Object doProfiling(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {

  String taskName = createTaskName(proceedingJoinPoint);
    TaskTimer taskTimer = profilerThreadLocal.get();
    try {
      taskTimer.start(taskName);

      return proceedingJoinPoint.proceed();
    } finally {
      taskTimer.stop();

      if (taskTimer.getTaskCount() == 0) {
        doLogging(proceedingJoinPoint.getTarget().getClass(), taskTimer.printSummary());
        profilerThreadLocal.remove();
      }
    }
  }

  private String createTaskName(ProceedingJoinPoint proceedingJoinPoint) {
    return new StringBuffer(proceedingJoinPoint.getTarget().getClass().getName())
        .append(".")
        .append(proceedingJoinPoint.getSignature().getName())
        .toString();
  }

  private void doLogging(Class clazz, String prettyPrint) {
    LogFactory.getLog(clazz).info("\n\n" + prettyPrint + "\n");
  }

  private class ProfilerThreadLocal extends ThreadLocal {

    @Override
    protected TaskTimer initialValue() {
      return new TaskTimer(Thread.currentThread().getName());
    }
  }
}

Specifying the Pointcut

As with the Logging Aspect, the Profiling Aspect pointcut expression selects methods annotated with a specific annotation (the Profilable annotation). This obviously prohibits profiling code which you cannot modify (i.e. add the annotation) so you will probably want to use other criteria within the pointcut expression.

By default, Spring uses proxy based aspect orientated programming (AOP) which limits us to applying aspects to Spring beans (look at the spring documentation for further discussion). An alternative to proxy based AOP is to use AspectJ Load Time Weaving (LTW) which instruments the code when loaded by the class loader.

To enable LTW, a configuration file (aop.xml) must be placed in a META-INF directory on the classpath. Within the aop.xml file, the aspect and the classes to be weaved must be specified. The pointcut expression can also be specified but I will leave this for you to look into.

<aspectj>
  <weaver>
    <!-- only weave classes in our application-specific packages -->
    <include within="net.thoughtforge.service.*"/>
  </weaver>

  <aspects>
    <!-- weave in just this aspect -->
    <concrete-aspect name="profilingAspect" extends="net.thoughtforge.aspect.ProfilingAspect">
      <pointcut name="profilingPointcut" expression="execution(* *(..)) && @annotation(net.thoughtforge.aspect.Profilable)"/>
      </concrete-aspect>
  </aspects>
</aspectj>

The other thing that needs to be done is to instruct the JVM to have AspectJ perform the LTW when a class is loaded. To do this specify the following JVM parameter (inserting your own path):

-javaagent:{path-to}\spring-agent-2.5.6.jar

Specifying the spring agent as opposed to the AspectJ agent has some advantages discussed within the Spring documentation.

Testing the Profiling Aspect

In this instance, rather than create a unit test to test the Profiling Aspect, I have created one to demonstrate it in action. I created a simple service annotated with the Profilable annotation. Invocations of methods within this service will be profiled and the profiling metrics will be output by the logging framework.

package net.thoughtforge.aspect;

import net.thoughtforge.service.ExampleService;

import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.test.context.ContextConfiguration;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;

@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration(locations = {
  "/applicationContext/applicationContext-aspect.xml",
  "/applicationContext/applicationContext-service.xml",
  "/applicationContext/applicationContext.xml" })
public class ProfilingAspectTest {

  @Autowired
  public ExampleService exampleService;

  @Test
  public void doSomething() throws Exception {
    exampleService.doSomething();
  }

  @Test
  public void doSomethingWithSomething() throws Exception {
    exampleService.doSomethingWithSomething();
  }

  @Test
  public void doSomethingWithSomethingFiftyTimes() throws Exception {
    exampleService.doSomethingWithSomethingFiftyTimes();
  }
}

Executing the profiling aspect test results in the following logging output:

TaskTimer 'main': running time (millis) = 109

-------------------------------------------------------------------------------------------------
Invocations	Total Time(%)	Total Time(ms)	Min Time	Max Time	Average Time(ms)	Task Name
-------------------------------------------------------------------------------------------------
00001		100%		00109		00109		00109		00109			net.thoughtforge.service.ExampleService.doSomething

TaskTimer 'main': running time (millis) = 63

-------------------------------------------------------------------------------------------------
Invocations	Total Time(%)	Total Time(ms)	Min Time	Max Time	Average Time(ms)	Task Name
-------------------------------------------------------------------------------------------------
00001		002%		00001		00001		00001		00001			net.thoughtforge.service.ExampleService.getSomething
00001		100%		00063		00063		00063		00063			net.thoughtforge.service.ExampleService.doSomethingWithSomething

TaskTimer 'main': running time (millis) = 4027

-------------------------------------------------------------------------------------------------
Invocations	Total Time(%)	Total Time(ms)	Min Time	Max Time	Average Time(ms)	Task Name
-------------------------------------------------------------------------------------------------
00001		100%		04027		04027		04027		04027			net.thoughtforge.service.ExampleService.doSomethingWithSomethingFiftyTimes
00050		001%		00050		00001		00001		00001			net.thoughtforge.service.ExampleService.getSomething
00050		098%		03966		00079		00095		00079			net.thoughtforge.service.ExampleService.doSomethingWithSomething

This article should act as a starting point for exploring Spring AOP and AspectJ further. You can download the profiling aspect code and play around with Proxy based AOP and LTW, specifying the pointcut expression in the aop.xml file or within code etc.

(No Ratings Yet)

 Loading ...

• Previous Entry: jBPM Developer Guide
• Next Entry: The Soul of a New Machine