[SOLVED] Overhead due to AOP logging

Overhead due to AOP logging

I am planning to log the execution time of all methods for a REST API. To accomplish this, I use AOP as follows:

@Aspect
@Component
@Slf4j
@ConditionalOnExpression("${aspect.enabled:true}")
public class ExecutionTimeAdvice {
  @Around("@annotation(TrackExecutionTime)")
  public Object executionTime(ProceedingJoinPoint point) throws Throwable {
    long startTime = System.currentTimeMillis();
    Object object = point.proceed();
    long endtime = System.currentTimeMillis();
    log.info("Class Name: " + point.getSignature().getDeclaringTypeName() + ". Method Name: " + point.getSignature().getName() + ". Time taken for Execution is : " + (endtime - startTime) + "ms");
    return object;
  }
}

@Service
public class MessageService {
  @TrackExecutionTime
  @Override
  public List<AlbumEntity> getMessage() {
    return "Hello message";
  }
}

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

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

But there is a performance overhead by using AOP. There is a lag in the service response time around more than 200ms, i.e. performance overhead.

What efficient ways are there to implement the execution time logging? Can I use AspectJ for better efficiency? Or there any alternatives to AOP? Can we use AOP in a more efficient way?

Solution

If you include Micrometer, Prometheus, and Spring Boot Actuator you may reduce the 200+ms overhead. My guess is the 200+ms overhead is due to logging. This article gives a good description of using the @Timed annotation to measure public method execution time. Timer information such as maximum and total execution time and number of events is presented when you hit the actuator/promethius endpoint. You would derive the average from the total and number of events.