Search code examples
springspring-webfluxspring-aopproject-reactor

Spring WebFlux endpoint performance logger


Do you know any good practices to log Spring WebFlux controller endpoint performance to keep reactive nature? Seems the following principle wouldn't work because it will block the IO as the ProceedingJoinPoint doesn't return Publisher<> , it returns just an object

@Aspect
@Component
@Slf4j
public class LoggingAspect
{

    //AOP expression for which methods shall be intercepted
    @Around("execution(* com.company.service..*(..)))")
    public Object profileAllMethods(ProceedingJoinPoint proceedingJoinPoint) throws Throwable
    {
        MethodSignature methodSignature = (MethodSignature) proceedingJoinPoint.getSignature();

        //Get intercepted method details
        String className = methodSignature.getDeclaringType().getSimpleName();
        String methodName = methodSignature.getName();

        final StopWatch stopWatch = new StopWatch();

        //Measure method execution time
        stopWatch.start();
        Object result = proceedingJoinPoint.proceed();
        stopWatch.stop();

        //Log method execution time
        log.info("Execution time of " + className + "." + methodName + " :: " + stopWatch.getTotalTimeMillis() + " ms");

        return result;
    }
}

Solution

  • Actually as mentioned @Toerktumlare in the comments proceedingJoinPoint.proceed() returns the type of object whatever is you controller endpoint return type, so it is possible to keep reactive nature. Note .subscribeOn(Schedulers.parallel()) is optional here, that is for my back code to support parallelism. Posting the solution for this:

    @Aspect
    @Component
    @Slf4j
    public class LoggingAspect
    {
    
        //AOP expression for which methods shall be intercepted
        @Around("execution(* com.company.service..*(..)))")
        public Object logEndpointPerformance(ProceedingJoinPoint proceedingJoinPoint) throws Throwable
        {
            MethodSignature methodSignature = (MethodSignature) proceedingJoinPoint.getSignature();
    
            //Get intercepted method details
            String className = methodSignature.getDeclaringType().getSimpleName();
            String methodName = methodSignature.getName();
    
            final StopWatch stopWatch = new StopWatch();
    
            //Measure method execution time
            stopWatch.start();
            Object result = proceedingJoinPoint.proceed();
    
            if(result instanceof Mono){
                return ((Mono)result).subscribeOn(Schedulers.parallel()).flatMap(r -> {
                    logExecutionTime(className, methodName, stopWatch);
                    return Mono.just(r);
                });
            }
            else if(result instanceof Flux){
                return ((Flux<Object>)result).subscribeOn(Schedulers.parallel()).collectList().flatMapMany(r -> {
                    logExecutionTime(className, methodName, stopWatch);
                    return Flux.fromIterable(r);
                });
            }
            else{
                logExecutionTime(className, methodName, stopWatch);
                return result;
            }
        }
    
        private void logExecutionTime(final String className, final String methodName, final StopWatch stopWatch){
            stopWatch.stop();
            //Log method execution time
            log.debug("[ " + stopWatch.getTotalTimeMillis() + " mls ] lasted execution of" + className + "." + methodName );
        }
    }