<img height="1" width="1" style="display:none;" alt="" src="https://px.ads.linkedin.com/collect/?pid=299788&amp;fmt=gif">

Logging Method Execution Time Using Aspects

Development Process, Software Development, Software Solutions, Java

By Thomas Behlau

Logging Method Execution Time Using Aspects

At some point during a project, you will invariably run into the problem of needing to record the execution time of a portion of your system. In the case I recently ran into, I suspected that the performance of an external web service call degraded over time. So what was the simplest solution to show the execution times for these calls without having to install additional tools?

The first idea that came to mind was using a Java Aspect to wrap the method execution. Searching for an example implementation, I found a few samples. The following looked promising:

@Aspect
public class LogExecutionTime {
private static final String LOG_MESSAGE_FORMAT = &quot;%s.%s execution time: %dms&quot;;
private static final Log LOG = LogFactory.getLog(LogExecutionTime.class);
@Pointcut(&quot;execution(something goes here&quot;)
public void myPointCut() {}
@Around(&quot;myPointCut()&quot;)
public Object logTimeMethod(ProceedingJoinPoint joinPoint) throws Throwable {
StopWatch stopWatch = new StopWatch();
stopWatch.start();
Object retVal = joinPoint.proceed();
stopWatch.stop();
logExecutionTime(joinPoint, stopWatch);
return retVal;
}
private void logExecutionTime(ProceedingJoinPoint joinPoint, StopWatch stopWatch) {
String logMessage = String.format(LOG_MESSAGE_FORMAT, joinPoint.getTarget().getClass().getName(), joinPoint.getSignature().getName(), stopWatch.getTime());
LOG.info(logMessage.toString());
}
}
That was easy. The only part of the implementation I still needed was the pointcut expression. I have always hated the fact that I have to know in advance where to apply the aspect, so I decided to use a custom annotation. I created a small annotation class:

@Retention(RetentionPolicy.RUNTIME)
@Target(value={ElementType.METHOD})
public @interface LogMe {
String value() default &quot;&quot;;
}
After implementing the annotation I had to make some adjustments to the implementation of the aspect.

@Pointcut(&quot;execution(@com.somecompany.erp.util.LogMe * *(..))&quot;)
public void isAnnotated() {}
@Around(&quot;isAnnotated()&quot;)
public Object logTimeMethod(ProceedingJoinPoint joinPoint) throws Throwable {

After this piece, I only needed to add the annotation @LogMe to a method and the execution would be logged to the logger configured in the log4j.properties.


The entire implementation took about 15-20 minutes and gave me a flexible tool to allow me to log the execution time of any method call, simply by adding my annotation.

Managing JIRA at Scale White Paper

TAGS: Development Process, Software Development, Software Solutions, Java

0 replies

Leave a Reply

Want to join the discussion?
Feel free to contribute!

Subscribe to Our Newsletter

Recent Blog Posts