Aspect-oriented programming is nothing new, and the capability to create aspects in Java has been available since at least version 1.3 of the JDK.

Creating and wiring aspects is harder the old way than it is with something like Spring, but in some cases, adding Spring to the project is not an option.

In this lesson, we will build a simple aspect that logs long running queries in iBATIS.

The code in this lesson was written against the latest iBATIS 2 (from SVN), but should work with 2.1.7, or earlier, since it lives outside of iBATIS.

This example does use the iBATIS DAO, but could be adapted to use anything where you are using separate interfaces and implementations for your DAOs.

The first step is to create a DaoManager factory of some kind. This one is very simple, it just instantiates a DaoManager in a static block, and returns that instance in it's getInstance method.
Here is the DaoMangerFactory source (w/o the package and imports):

 1 public class DaoManagerFactory {
 2 	private static DaoManager daoManager;
 3 	private static final Logger log = Logger.getLogger(DaoManagerFactory.class);
 4 	static {
 5 		try {
 6 			Reader reader = Resources.getResourceAsReader("dao.xml");
 7 			DaoManagerFactory.daoManager = DaoManagerBuilder.buildDaoManager(reader);
 8 			LoggingDaoManager ldm;
 9 			ClassLoader classLoader;
10 			if(Logger.getLogger(LoggingDao.class).isEnabledFor(Priority.WARN)){
11 				ldm = new LoggingDaoManager(DaoManagerFactory.daoManager);
12 				classLoader = Thread.currentThread().getContextClassLoader();
13 				daoManager = (DaoManager) Proxy.newProxyInstance(
14 						classLoader,
15 						new Class []{DaoManager.class},
16 						ldm);
17 			}
18 		} catch (IOException e) {
19 			DaoManagerFactory.log.error(e.getLocalizedMessage(), e);
20 		}
21 	}
22
23 	/**
24 	 * @return DaoManager
25 	 */
26 	public static DaoManager getInstance() {
27 		return DaoManagerFactory.daoManager;
28 	}
29 }
30 

Let's dissect that code. First off, we declare our DaoManager instance, and create a log. I am using Log4J, but converting it to commons-logging is a pretty trivial exercise.

Next comes the static block, and this is where the interesting stuff happens.

First, we initialize our DaoManger instance. This is nothing new if you have been using the iBATIS DAO, you have seen this code already.

Now it gets into some new stuff. We check the log level of the log associated with the LoggingDao class. If it is set to WARN or higher, we create an instance of our LoggingDaoManager, and replace the DaoManger instance with the wrapped version.

OK, here is the next piece of the puzzle: The LoggingDaoManager, which is responsible for creating and returning the proxied DAOs that will log long running SQL statements.

 1 public class LoggingDaoManager implements InvocationHandler {
 2 	private DaoManager delegate;
 3
 4 	public LoggingDaoManager(DaoManager delegate) {
 5 		this.delegate = delegate;
 6 	}
 7
 8 	public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
 9 		Object retVal = method.invoke(delegate, args);
10 		if(method.getName().equals("getDao")){
11 			ClassLoader cl = Thread.currentThread().getContextClassLoader();
12 			LoggingDao ld = new LoggingDao(retVal);
13 			Class[] cls = new Class []{(Class)args[0]};
14 			retVal = Proxy.newProxyInstance(cl, cls, ld);
15 		}
16 		return retVal;
17 	}
18 }
19 

This class has two purposes - first, it saves the DaoManager passed in from the constructor. It does this because in the invoke method, we need to use it to get the return value.

In the invoke method, we call the default implementation to do whatever it does, and then if the getDao method was called, we wrap the returned DAO in our LoggingDao class.

Finally, we are at the final class, the LoggingDao class. This is the class that is responsible for actually timing and logging the mapped statements.

 1 public class LoggingDao implements InvocationHandler {
 2 	private Object delegate;
 3 	private static final Logger log = Logger.getLogger(LoggingDao.class);
 4
 5 	public LoggingDao(Object delegate) {
 6 		this.delegate = delegate;
 7 	}
 8
 9 	public Object invoke(Object proxy, Method method, Object[] args) {
10 		Object retVal;
11 		long start;
12 		long elapsed;
13
14 		try {
15 			start = System.currentTimeMillis();
16 			retVal = method.invoke(delegate, args);
17 			elapsed = System.currentTimeMillis() - start;
18 		} catch (Exception e) {
19 			throw new DaoException(e.getCause());
20 		}
21
22 		String methodName = method.getDeclaringClass().getName() + "." + method.getName();
23
24 		if (elapsed < 1000) {
25 			log.info(methodName + " in " + elapsed + "ms.");
26 		} else {
27 			log.warn(methodName + " in " + elapsed + "ms.");
28 		}
29
30 		return retVal;
31 	}
32 }
33 

In this class, we see a similar pattern as the LoggingDaoManager - we save the original object in the constructor so we can use it to delegate calls, then we wrap calls to it in our logic to measure the time, and log the method call as a warning if it takes longer than 1000ms. If it runs in less time than that, we log it as and informational message.