Performance Logging with Spring Boot and AOP

Question

I'm trying to implement performance logging based off of this post: http://www.baeldung.com/spring-performance-logging. I'd like to log each controller endpoint and every database request. If you would like to see the full project, you can find it here. When I hit the endpoints nothing is logged. Placing a breakpoint within the interceptor class it doesn't stop either. I've already set my logging for the packages to the trace level. What am I missing? I believe it's something to with the @PointCut but after looking at the docs I believe I have it correct.

Interceptor

public class PerformanceMonitorInterceptor extends AbstractMonitoringInterceptor
{
    @Override
    protected Object invokeUnderTrace(MethodInvocation methodInvocation, Log log) throws Throwable
    {
        String name = createInvocationTraceName(methodInvocation);
        StopWatch stopWatch = new StopWatch();
        stopWatch.start();
        log.trace(String.format("Method %s execution start at %s", name, LocalDateTime.now()));

        try
        {
            return methodInvocation.proceed();
        }
        finally
        {
            stopWatch.stop();
            log.trace(String.format("Method %s execution took %dms (%s)", name,
                stopWatch.getTotalTimeMillis(), DurationFormatUtils
                    .formatDurationWords(stopWatch.getTotalTimeMillis(), true, true)));
        }
    }
}

Configuration

@Configuration
@EnableAspectJAutoProxy
@Aspect
public class ContactControllerPerfLogConfig
{
    @Bean
    public PerformanceMonitorInterceptor performanceMonitorInterceptor()
    {
        return new PerformanceMonitorInterceptor();
    }

    // Any public method on the ContactController
    @Pointcut("execution(public * org.example.phonebookexample.app.contact.ContactController.*(..))")
    public void contactControllerMonitor()
    {
    }

    @Bean
    public Advisor contactControllerMonitorAdvisor(
        PerformanceMonitorInterceptor performanceMonitorInterceptor)
    {
        AspectJExpressionPointcut pointcut = new AspectJExpressionPointcut();
        pointcut.setExpression("org.example.phonebookexample.app.contact.ContactControllerPerfLogConfig.contactControllerMonitor()");
        return new DefaultPointcutAdvisor(pointcut, performanceMonitorInterceptor);
    }
}

Answer 1

I never understood the importance of AbstractTraceInterceptor if you are going to customize it.

I always felt too much code for me which can be achieved by a simple @Around advice if you already have @Aspect in place.

    @Around("execution(* com..*.*(..))")
    public Object logStartAndEnd(ProceedingJoinPoint pjp) throws Throwable{
        long startTime = System.currentTimeMillis();
        String className = pjp.getTarget().getClass().getCanonicalName();
        String methodName = pjp.getSignature().getName();
        log.info("started method : " + className+"."+methodName);

        Object obj;
        try {
            obj = pjp.proceed();
            log.info("finished method : " + className+"."+methodName);
            return obj;
        } catch (Throwable e) {
            throw e;
        }finally {
            log.info("Method "+className+"."+methodName+" execution lasted:"+((System.currentTimeMillis() - startTime )/1000f)+" seconds");
        }
    }

Answer 2

AbstractTraceInterceptor implements MethodInterceptor and has its invoke() method implemented as follows:

public Object invoke(MethodInvocation invocation) throws Throwable {
    Log logger = getLoggerForInvocation(invocation);
    if (isInterceptorEnabled(invocation, logger)) {
        return invokeUnderTrace(invocation, logger);
    }
    else {
        return invocation.proceed();
    }
}

Therefore the logger for the Interceptor class needs to be set to TRACE. For the basic PerformanceMonitorInterceptor, that will be org.springframework.aop.interceptor.PerformanceMonitorInterceptor. Since you've written your own interceptor, you'll have to set logging level for your own class. Take a look at JamonPerformanceMonitorInterceptor for an example of an alternative approach, allowing to track all invocations regardless of logging level, if required.

For the sake of completeness, I'll also post an xml configuration example, because when it comes to AOP, Spring java configs are not so elegant compared to xml configs:

<bean id="performanceMonitorInterceptor" class="org.springframework.aop.interceptor.PerformanceMonitorInterceptor"/>

<aop:config>
    <aop:pointcut id="contactControllerMonitor" expression="execution(public * org.example.phonebookexample.app.contact.ContactController.*(..))" />
    <aop:advisor id="contactControllerMonitorAdvisor" pointcut-ref="contactControllerMonitor" advice-ref="performanceMonitorInterceptor"/>
</aop:config>

This config can be imported into your java configuration as follows:

@ImportResource("classpath:/aop-config.xml")
public class MainConfig { ... }