openengine

Derailed in Uncle Gates' Victory Garden.

Deep Logging Using Spring and AOP (SMEG)

Published Thursday, May 18, 2006 by Chris Stevenson | E-mail this post

For sometime I've been thinking about open sourcing a small piece of Java code I wrote that makes the analysis of sub components of a system at runtime easier. My requirement was to create a piece of code which can tell me how the separate libraries of the services I was working on at the time were behaving at runtime. Was LibA running very slowly, was LibB throwing exceptions that were being muffled higher up the chain? So to meet this need I wrote SMEG.

The code for SMEG is broken into 2 parts, the first is an AOP interceptor that you wrap around particular components in a system. This interceptor doesn't do anything fancy, it just generates an event from the application context and then carries on execution.

The second part of the system is a listener for these events. In theory you could do anything you what with these events, in practice what I've done is capture these events and formulate a fake stack from them giving the percentage of the total execution time of each wrapped sub component.

What does this mean to me, I hear you lament? Well, for example say I have a service called the AeroplaneService. This service is a way of exposing on the wire a bunch of macro functionality of an aeroplane. Some of the operations on my service could be:


package org.openengine.service.aerplane;

public interface AeroplaneService {
	public void takeOff() 	throws AeroPlaneException;
	public void land() 		throws AeroPlaneException;
}

These operations represent quite coarse grained operations, there is a lot of things going on when a plane takes off. In reality what would happen is these methods would delegate to other services. Some examples of these services might be:



public interface LandingGearService {
	public void liftUp() 	                throws AeroPlaneException;
	public void lower() 		throws AeroPlaneException;
}

public interface AeroplaneEngineService {
	public void increaseThrottle() 	                throws AeroPlaneException;
	public void decreaseThrottle() 	throws AeroPlaneException;
}

Now if I wanted to inspect the running of a plane during flight, I could write logging statements throughout the code to say something like "BEFORE: liftUp() time=12:51:54pm" and "AFTER: liftUp() time=12:51:58pm". And then I could extrapolate from this the time required to perform the lift up operation. But this feels invasive, lots of code statements around clogging up business logic, lots of post processing to get anything meaningful. Ideally what I'd like is a way to record this information in a way that has no impact on my code, that can be turned off and on in config and that gives me the running cost of the liftUp method on the LandingGearService as a percentage of the total of the AeroplaneServices takeOff() method. This is what SMEG was designed to do.

So what we do is wrap our AOP interceptor around the AeroplaneService, the LandingGearService and the AeroplaneEngineService. The in the background SMEG captures the events being generated and records them against a thread, pairing the start of a method with its completion and then writing out the result to a log file.

So what we end up with is a log like this:


2006-02-24 11:36:30,716|[Thread-1]|020.00|ms|100.00%|d=0|s=2|AeroplaneService.takeOff() : void
2006-02-24 11:36:30,716|[Thread-1]|010.00|ms|050.00%|d=1|s=1|		LandingGearService.liftUp() : void
2006-02-24 11:36:30,716|[Thread-1]|010.00|ms|050.00%|d=1|s=0|		AeroplaneEngineService.increaseThrottle() : void

We can see from this that inside of the AeroplaneService.takeOff() method we executed two methods on our other wrapped interfaces, AeroplaneEngineService.increaseThrottle() and LandingGearService.liftUp(), each one took 50% of the time of the call to execute and in real terms the time was 10 ms each.

This allows you to produce simple runtime statistics for your system without having to trawl through your code writing start and stop log statements.

Please watch this space and openengine.org for when SMEG becomes available.

Chris