Using Spring AOP to trace invocations

How often do you write something like this?

public void foo(){
logger.debug("entering foo");
....
logger.debug("leaving foo");
}

If your answer is "often enough", then you should consider the following info. Anyone using Spring framework can seamlessly integrate trace logging into his application, just with slight modification to their spring context configs. In this post I will describe how to trace your code using DebugInterceptor (or any other interceptor of your choice).

The idea behind the proposed solution is to wrap the bean, which invocations you are going to trace, with a proxy that has SimpleTraceInterceptor or DebugInterceptor in the interceptorNames property. The interceptors mentioned are implementations of around advice that will write all the invocations' details to some logger (the way we choose our logger is discussed later on). This Interceptors are provided with Spring core library along with CustomizableTraceInterceptor, PerformanceMonitorInterceptor and few others. I guess, an example is the best way to show how it works.

Consider this simple program: two beans, one Spring context config, and one entry-point class, that just calls the first bean's method( so it is omitted on this page).

Bean1:


Bean2:


The Spring Context:



Running this code we get the following output:

23:13:04,348 TRACE [com.blogspot.mikler.java.Bean1] - Entering method 'entryPoint' of class [com.blogspot.mikler.java.Bean1]
23:13:04,349 TRACE [com.blogspot.mikler.java.Bean2] - Entering method 'importantMethod' of class [com.blogspot.mikler.java.Bean2]
23:13:04,349 INFO [com.blogspot.mikler.java.Bean2] - Doing job for 3 seconds
23:13:07,349 TRACE [com.blogspot.mikler.java.Bean2] - Exiting method 'importantMethod' of class [com.blogspot.mikler.java.Bean2]
23:13:07,350 TRACE [com.blogspot.mikler.java.Bean2] - Entering method 'doSomethingQuick' of class [com.blogspot.mikler.java.Bean2]
23:13:07,351 INFO [com.blogspot.mikler.java.Bean2] - doing something quick with param = a job
23:13:07,351 TRACE [com.blogspot.mikler.java.Bean2] - Exiting method 'doSomethingQuick' of class [com.blogspot.mikler.java.Bean2]
23:13:07,351 INFO [com.blogspot.mikler.java.Bean1] - All jobs done
23:13:07,351 TRACE [com.blogspot.mikler.java.Bean1] - Exiting method 'entryPoint' of class [com.blogspot.mikler.java.Bean1]

I hope the source code tells the story.

Several points that should be stressed:

• One should decide to use Dynamic Logger or not (see useDynamicLogger property of the DebugInterceptor). If the dynamic logger is used, then invocations' log messages will be written to the logger of respective bean class (log4j.logger.com.blogspot.mikler.java.* loggers in our case). Otherwise the logger of the respective Interceptor will be used, one for all of the beans.
• Make sure you enable the trace level for the selected logger. Because for optimization purposes the Interceptors don't make any job, saving your operation time, if this logging level for the logger they look up is not enabled.

To try yourself you can checkout sourcecode of this sample by running
svn co http://miklerjava.googlecode.com/svn/trunk/samples/SpringTracing springtracingsample