Spring AOP method execution time and Environment Variable controlled logging

Aspect Oriented Programming (AOP) allows to “define cross-cutting concerns that can be applied across separate, very different, object models”. AOP complements Object Oriented Programming by increasing modularity with applying common behavior to multiple non-related object models.

If we need to define AOP in a one liner then “AOP as an interceptor for method calls, where you can add additional functionality without actually modifying the method”

One such application that AOP can be made use of is to profile the method execution times for a Java service.

Introducing AOP for method execution time profiling does not necessarily involve changing any part of your existing code. The below two steps can give you the power of profiling functionality

Step 1 : Add a dependency for AOP (Gradle) in your build.gradle script within the dependencies section.

implementation( group: 'org.springframework.boot', name: 'spring-boot-starter-aop', version: '2.5.7')

Step 2 : Add the below program to your source package root folder. ConditionalOnExpression annotation helps you to control if you wish to enable or disable profiling in certain execution environments with environment variables.

package foo.bar;


import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.boot.autoconfigure.condition.ConditionalOnExpression;
import org.springframework.stereotype.Component;

@Aspect
@Component
@ConditionalOnExpression("#{systemEnvironment['AOP_LOG_METHOD_TIMING'] == 'true'}") // Optional if you wish to control
public class Profile {


    private static final Logger LOGGER = LogManager.getLogger(Profile.class);
    @Around("execution(* foo.bar..*(..))")
    public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
        final long start = System.currentTimeMillis();

        final Object proceed = joinPoint.proceed();

        final long executionTime = System.currentTimeMillis() - start;

        LOGGER.info("ExecutionTime {}: {} [ms]\n",
                joinPoint.getSignature().getDeclaringTypeName()+"."+joinPoint.getSignature().getName(), executionTime);

        return proceed;
    }
}
@ConditionalOnExpression("#{systemEnvironment['AOP_LOG_METHOD_TIMING'] == 'true'}")
public class Profile {


    private static final Logger LOGGER = LogManager.getLogger(Profile.class);
    @Around("execution(* foo.bar..*(..))")
    public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
        final long start = System.currentTimeMillis();

        final Object proceed = joinPoint.proceed();

        final long executionTime = System.currentTimeMillis() - start;

        LOGGER.info("ExecutionTime {}: {} [ms]\n",
                joinPoint.getSignature().getDeclaringTypeName()+"."+joinPoint.getSignature().getName(), executionTime);

        return proceed;
    }
}