Mikhail has posted 3 posts at DZone. View Full User Profile

Using Spring AOP to Trace Invocation

07.23.2009
| 17919 views |
  • submit to reddit

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 DebugInterceptor (or any other interceptor of your choice) 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 Spring AOP

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:

package com.blogspot.mikler.java;

import org.apache.log4j.Logger;

public class Bean1 {

Logger logger = Logger.getLogger(Bean1.class);

Bean2 bean2;

public void entryPoint(){
bean2.importantMethod();
bean2.doSomethingQuick("a job");
logger.info("All jobs done");
}

public void setBean2(Bean2 bean2) {
this.bean2 = bean2;
}

}

 Bean2:

package com.blogspot.mikler.java;

import org.apache.log4j.Logger;

import java.text.MessageFormat;

public class Bean2 {
Logger logger = Logger.getLogger(Bean2.class);

public void importantMethod(){
logger.info("Doing job for 3 seconds");
try {
Thread.sleep(3000);
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
}

public void doSomethingQuick(String param1) {
logger.info(MessageFormat.format("doing something quick with param = {0}",param1));
}
}

The Spring Context:

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:aop="http://www.springframework.org/schema/aop"
xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd">

<bean id="simpleTraceInterceptor" class="org.springframework.aop.interceptor.SimpleTraceInterceptor">
<property name="useDynamicLogger" value="true"/>
</bean>
<bean id="debugInterceptor" class="org.springframework.aop.interceptor.DebugInterceptor">
<property name="useDynamicLogger" value="true"/>
</bean>

<bean id="bean1" class="org.springframework.aop.framework.ProxyFactoryBean">
<property name="target">
<bean class="com.blogspot.mikler.java.Bean1">
<property name="bean2" ref="bean2"/>
</bean>
</property>
<property name="interceptorNames" value="simpleTraceInterceptor"/>
</bean>

<bean id="bean2" class="org.springframework.aop.framework.ProxyFactoryBean">
<property name="target">
<bean class="com.blogspot.mikler.java.Bean2"/>
</property>
<property name="interceptorNames" value="simpleTraceInterceptor"/>
</bean>

</beans>

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 use DynamicLogger 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.

 Instructions about how to check out the source code for this article you can find in the original post.

Originally posted on miklerjava.blogspot.com

Published at DZone with permission of its author, Mikhail Kolesnik.

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)

Comments

Rogerio Liesenfeld replied on Thu, 2009/07/23 - 2:08pm

Why not simply use the debugger instead?

In IDEA at least, I can set a "method breakpoint" in any method and configure the breakpoint so that the executing thread is not suspended, but instead messages like "Method 'foo' entered at ..." and "Method 'foo' is about to exit at ..." are written to the console. And I can even specify an arbitrary Java expression (referencing any parameters or local variables) to be evaluated and printed for each execution of the method.

All this without writing a single line of code (Java or XML).

Mikhail Kolesnik replied on Thu, 2009/07/23 - 3:16pm in response to: Rogerio Liesenfeld

Hi, Rogerio.

 This smells like a holywar, but as per my experiencewhlie developing rather complex applications their behavior may varry dramaticly on development and production environments. And I don't think you will be able to debug production instance of your application. Meanwhile you might be unable as well to reproduce the issue in your development env.

Also I would like to mention that some people belive (and I do agree with them) that debugging is a last resort for solving an issue in your code. Good programmers use configurable and verbose logging in their application that allows then to identify the issue without using a debugger. And I really advise you to follow this best practice. Try to google for "why logging is better than debugging.

Best Regards,
Mikhail.

Liam Knox replied on Thu, 2009/07/23 - 10:24pm

I expect the are a lot of subtleties that you are failing to mention.

If this using CGLIB proxies, your beans would have to be none final and have default constructors. You would have the self reference issue interms of calling private methods. Any code that would be using instanceof check may well be affected. This could alter the nature of the way your application behaves

Sure this is neat and no doubt usefull, but it has floors. If you really wanted a more comprehensive general solution AspectJ would be a better bet.

Mikhail Kolesnik replied on Fri, 2009/07/24 - 12:57am in response to: Liam Knox

Cool! Thank you for this comment. It worths an article.

Andrei Vishnevsky replied on Fri, 2009/07/24 - 11:23am

I don't want to tell anything bad about the article. It is clear and short enough. Well done. But I always fill pain when we start talking about AOP. First of all AOP appeared as scientific project many years ago. The side effect is the strange and intricated terminology. For beginners who knows Java but meet AOP first time there are minimal associations between AOP and Java well known terminology and patterns. Secondly, frankly speaking I prefer to insert debug where I want to have manually instead of going through the XMLs. Moreover generally you should not do it often, only if there is necessity to fix a bug (at least my experience proves it :)).
And at last general thought. AOP comes to Java since Java as an OOP language has got limited and simplified OOP model implementation. The well designed languages (like Ruby or other Smalltalk successors) allow developers do everything using language facilities. That is why Java gets more and more crutches. Actually Java evolution has been completed after Java 1.2 appeared on market.

Rogerio Liesenfeld replied on Fri, 2009/07/24 - 6:42pm in response to: Mikhail Kolesnik

Well, in my experience developing complex applications, I have used both logging and the debugger. I sometimes found problems that only happened in production, and was usually able to find the cause through remote debugging, when examining the log files failed. Most of the times, though, the basic info collected in the logs was enough to understand and solve the problem.

Debugging is a last resort, but a powerful and effective one. Often, however, developers simply don't know how to do it well.

Verbose logging or tracing, in my experience, is useless. Normally, a full stack trace with some additional contextual information is enough to clarify the cause of the error.

So, yes, logging is usually better then debugging, if not done in excess.

Rogerio Liesenfeld replied on Sat, 2009/07/25 - 10:23am in response to: Mikhail Kolesnik

Just for fun, I did try googling for "why logging is better than debugging".

Unfortunately, I could not find a single relevant page. Can you?

However, I found this relevant question in the StackOverflow site.

Liam Knox replied on Sat, 2009/07/25 - 8:32pm in response to: Rogerio Liesenfeld

I dont think anyone can categorically say logging is better than debugging. Like so many other benine comparisons in software of A vs B, it doesnt really address the point. I would say both are powerfull and needed tools/techniques, and the ability to make tracing easier, less boilerplate and less intrusive is a good thing. I would say in a any multithreaded environment a debugger will oftern prove less value as bugs will often be time related and therefore impacted by the debugging process in itself. Also enivorment concerns can make certain situtations inappropriate for debugging, production for example.

I would just see logging and debugging along with JMX as tools to be used in tracking of bugs, performance issues and general application runtime concerns.

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.