Sometimes when using Spring in your app you want to profile your methods to see how long it takes for a method to complete. If you don’t have access to software like JProfiler you can accomplish this quickly with some AOP magic in Spring.
Notice that what’s important about this tutorial is not actually to profile time for methods calls. The real power is to use your custom annotations following the same pattern for this and other purposes such as Security, Cacheing of method return types, Transaction management, you name it…
This tutorial is available for download with svn:
svn checkout http://raulrajatutorials.googlecode.com/svn/trunk/ raulrajatutorials-read-only
Comments in the code itself should be self-explanatory if you already have some java + spring experience
And now to the point.
applicationContext.xml
<?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 http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-2.5.xsd"> <!-- A Service that performs some work --> <bean id="businessService" class="com.raulraja.service.impl.BusinessServiceImpl"/> <!-- A service interceptor that intercepts other services with methods annotated with @Profile --> <bean id="methodTimeProfiler" class="com.raulraja.util.aop.profile.MethodProfiler"/> <aop:config> <aop:aspect ref="methodTimeProfiler"> <aop:pointcut id="profiledMethods" expression="@annotation(com.raulraja.util.aop.profile.Profile)"/> <aop:around pointcut-ref="profiledMethods" method="profileMethod"/> </aop:aspect> </aop:config> <!-- This handler is actually not required but used for demonstrating the tutorial by invoking http://localhost:port/tutorialName --> <bean id="serviceInvokerHandler" class="com.raulraja.util.handler.impl.ServiceInvokerHandlerImpl" autowire="autodetect" /> </beans>
BusinessServiceImpl.java
package com.raulraja.service.impl; import com.raulraja.service.BusinessService; import com.raulraja.util.aop.profile.Profile; import org.apache.log4j.Logger; /** * This a very important service impl with methods that is doing something slow and needs to be profiled */ public class BusinessServiceImpl implements BusinessService { private final static Logger logger = Logger.getLogger(BusinessServiceImpl.class); /** * Do some work , by adding the @Profile annotation the interceptor provides advice */ @Profile public void doSomething() { logger.debug("nothing done for simplicity"); } }
Profile.java
package com.raulraja.util.aop.profile; /** * Marker for methods that will be profiled, By placing this annotation on a method spring will proxy the service and * call the interceptor that provides advice to the real method call */ public @interface Profile { }
MethodProfiler.java
package com.raulraja.util.aop.profile; import org.apache.log4j.Logger; import org.aspectj.lang.ProceedingJoinPoint; public class MethodProfiler { private final static Logger logger = Logger.getLogger(MethodProfiler.class); /** * Intercepts methods that declare com.company.project.util.aop.profiler.Profile and prints out the time it takes to complete * @param pjp proceeding join point * @return the intercepted method returned object * @throws Throwable in case something goes wrong in the actual method call */ public Object profileMethod(ProceedingJoinPoint pjp) throws Throwable { try { final boolean DEBUG = logger.isDebugEnabled(); long start = System.currentTimeMillis(); // Parse out the first arg String arg1 = ""; Object[] pjpArgs = pjp.getArgs(); if ((pjpArgs != null) && (pjpArgs.length > 0) && (pjpArgs[0] != null)) { arg1 = pjpArgs[0].toString(); } String logPrefix = null; if (DEBUG) { logPrefix = pjp.getSignature().getDeclaringTypeName() + "." + pjp.getSignature().getName() + " " + arg1; logger.debug(logPrefix + " START"); } Object retVal = pjp.proceed(); long end = System.currentTimeMillis(); long differenceMs = end - start; if (DEBUG) { logger.debug(logPrefix + " RETURN in " + differenceMs + " ms"); } return retVal; } catch (Throwable t) { logger.error("Interceptor caught error: " + t, t); throw t; } } }
And here it is actually running…


Nice. I’m trying something similar in my production code
And got
java.lang.IllegalStateException: Post-processor tried to replace bean instance of type [...] with (proxy) object of type [$Proxy78] – not supported for aspect-configured classes!
Seems that your solution does not really work to well with code that uses the Spring @Configurable annotation. Any ideas how to get round that?
@Configurable
Xyz {
@Autowired(required = true)
private OtherService otherService;
@Timer
public void timedMethod() {
}
}
Hi Natan,
I have not looked very deep into this issue but it looks like it might be related to the same problem as described here: http://olafsblog.sysbsb.de/?p=35
The first response links to the spring docs where it is described how it can be solved using aspectj.
The docs show how you can create aspectj aspects with spring and use the @Annotation in aspect bean with a @Aspect to intercept methods that contain a given annotation.
The docs also show how it is compatible with @Configurable.
http://static.springsource.org/spring/docs/2.5.x/reference/aop.html#aop-using-aspectj
Let me know if you can’t figure out and I will look further into it as it is interesting to me as well. If you do find it and you feel like sharing feel free to post it as comment.
Thanks
Hi Raul,
That indeed seems to be the problem. I have not looked at it since (too busy) but it is definitely something worth looking at.
regards, N