WTF is AOP?

When I first heard about AOP the story have unfolded pretty much the same way as when I’ve read about Spring framework for the first time. The issue with understanding what IoC is for was that it looks very interesting, but complicated. And probably one should have some sort of insight so see any benefits behind all the complexity he (she) is exposed to while reading the documentation.

With AOP the story is the same. “What are my benefits?” – is the very first question I’m asking any book or article that is telling me about Aspect, Advises and Joint-points. And usually I have to patiently read through several more boring definitions when the author gets to the point. So I’m going to save you some of your precious time. Let me try to explain what AOP is and how you can benefit from it, putting it as simple as possible.

When you write your code, besides main functionality, you usually need to do auxiliary things, like logging, security stuff (or put it nerdy: authentication and authorization), and you might need something like transaction handling. Without AOP you most likely will end up doing this things right next to your “important code”. And there are several issues with this:
Methods containing your “important code” will be overloaded with auxiliary code and will be harder to read and understand.

1. If you change the way you control user’s access to the system or the way you do logging or transaction handling, you’ll have to change it in each and every place you are doing that.
2. When and if you start reading on about AOP you will see such words as scattering and tangling, which also refer to such “bad” functionality.

So AOP is aimed to reduce your pain while dealing with the issues mentioned. The idea is that any kind of auxiliary functionality is extracted into separate code which is going to be applied to any existing model, so that code that is already in that model doing the same things can be removed. And this extracted code is called Advice (don’t ask me why).

Then you define where you want to call this Advise from. I.e. you might want to write logging messages before a specific method call. This place will be called Pointcut. And all together with Advice this will form Aspect.
You can see how it works with logging in my previous post “Using Spring AOP to trace invocations”.

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