Custom annotation to log method execution time

Logging the execution time taken by your code is a necessary requirement to debug which part of your code is taking more time. Normally what we do we put “System.currentTimeMillis()” at start of method and subtract this time from”System.currentTimeMillis()” again before method returns. Doing it this way pollute the code base unnecessarily.

Better way of implementing same functionality without polluting code base is using custom annotation and Aspect Oriented Programming.

We would leverage @Around AspectJ annotation for this. @Around — Run around the method execution.

We would define a custom annotation MethodStat and use this annotation as a pointcut, thus wherever this annotation appears on a method, logging aspect will run around that method execution and log the time taken by that method.

Annotation definition-

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface MethodStats {
}

Aspect definition-

@Aspect
@Component
public class Logger 
{
   private static org.slf4j.Logger logger = LoggerFactory.getLogger(Logger.class);
   @Around("execution(* *(..)) && @annotation(com.hexascale.MethodStats)")
    public Object log(ProceedingJoinPoint point) throws Throwable 
   {
      long start = System.currentTimeMillis();
       Object result = point.proceed();
       logger.info("className={}, methodName={}, timeMs={},threadId={}",new Object[]{
            MethodSignature.class.cast(point.getSignature()).getDeclaringTypeName(),
            MethodSignature.class.cast(point.getSignature()).getMethod().getName(),
            System.currentTimeMillis() - start,
            Thread.currentThread().getId()}
          );
       return result;
   }
}

Just put @MethodStat on any method, when this method will be called, time taken by method will be printed in logs.

Checkout fully working code from git. Import the project as maven project in any IDE and run main method in App class. There are two method which are annotated with @MethodStat test1 and test2, both method contains only Thread.sleep statement.

Method test1 sleeps for 1 second and produce following output-

16:45:39.759 [main] INFO com.hexascale.Logger — className=com.hexascale.MethodService, methodName=test1, timeMs=1022,threadId=1

Method test2 sleeps for 5 second and produce following output

6:45:44.762 [main] INFO com.hexascale.Logger — className=com.hexascale.MethodService, methodName=test2, timeMs=5000,threadId=1

timeMs is the execution time.

So using @MethodStat is much easier than putting System.currentTimeMillis() in all methods.