Is there a way to do one-time processing before an AOP around joinpoint to make my aspect more performant?

Question

I've got a custom @Traceable annotation with a TraceAspect implementation. We use the @Traceable annotation on methods where we want to log before and after the method invocation. We've just added the ability to specify a log level to use via value attribute within @Traceable (the old version always just used INFO). What I have works, but I am wondering if there is a way to make it more performant. Specifically, checking the value set on @Traceable for a given method could be done once at app startup if there was some sort of aspect context.

@Traceable annotation:

@Documented
@Retention(RUNTIME)
@Target(METHOD)
public @interface Traceable {

    Level value() default Level.INFO;
}

Current TraceAspect impl:

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.event.Level;
import org.springframework.stereotype.Component;

@Component
@Aspect
public class TraceAspect {

    @Around("@annotation(com.collaterate.logging.Traceable)")
    public Object traceAround(ProceedingJoinPoint joinPoint) throws Throwable {
        Traceable traceable = ((MethodSignature) joinPoint.getSignature()).getMethod().getAnnotation(Traceable.class);
        Logger classLog = LoggerFactory.getLogger(joinPoint.getSignature().getDeclaringType());
        LoggingHelper loggingHelper = getLoggingHelper(traceable, classLog);

        String methodName = joinPoint.getSignature().getName();
        loggingHelper.log("{}() - started", methodName);
        Object returnVal = joinPoint.proceed();
        loggingHelper.log("{}() - ended", methodName);

        return returnVal;
    }

    private LoggingHelper getLoggingHelper(Traceable traceable, Logger classLog) {
        if (Level.INFO == traceable.value() || null == traceable.value()) {
            // try to avoid the switch below... most of the time it will be INFO
            return (format, args) -> classLog.info(format, args);
        } else {
            switch (traceable.value()) {
                case ERROR :
                    return (format, args) -> classLog.error(format, args);
                case WARN :
                    return (format, args) -> classLog.warn(format, args);
                case DEBUG :
                    return (format, args) -> classLog.debug(format, args);
                case TRACE :
                    return (format, args) -> classLog.trace(format, args);
                default :
                    return (format, args) -> classLog.info(format, args);
            }
        }
    }

    @FunctionalInterface
    interface LoggingHelper {

        void log(String format, Object... args);

    }
}

The only other idea I had is to create multiple annotations (one for each log level) and then the TraceAspect would impl an @Around handler for each annotation and we avoid the reflection / switch at runtime. What I don't like about this is we already use the existing @Traceable annotation all over production code in multiple projects. I would like to keep the 1 annotation and allow it to specify log level via the attribute.

In theory, what I want to do should be possible since all the info is there at app startup when the proxy is created. There would just have to be some kind of context for each annotated method.

Answer 1

I have done something similar wrt to metrics. You can maintain a log registry with class and method pair as the key and LoggingHelper as the value.

If the class method pair doesn't have an entry in the log registry, create a logging helper and store it in the registry. The second time around, you just look it up in the registry.

The registry is a custom Spring bean which should be autowired into your aspect.

Here is an example of modified TraceAspect.

@Component
@Aspect
public class TraceAspect {

    private LogRegistry registry;

    @Autowired
    public TraceAspect(LogRegistry registry) {
        this.registry = registry;
    }

    @Around("@annotation(com.collaterate.logging.Traceable)")
    public Object traceAround(ProceedingJoinPoint joinPoint) throws Throwable {
        String loggerName = joinPoint.getSignature()
           .getDeclaringType().getCanonicalName() + "." 
              + joinPoint.getSignature().getName();

        LoggingHelper loggingHelper = registry.get(loggerName);
        if (loggingHelper == null) {
            Traceable traceable = ((MethodSignature) joinPoint.getSignature()).getMethod().getAnnotation(Traceable.class);
            Logger classLog = LoggerFactory.getLogger(joinPoint.getSignature().getDeclaringType());
            loggingHelper = getLoggingHelper(traceable, classLog);
            registry.put(loggerName, loggingHelper)
        }

        String methodName = joinPoint.getSignature().getName();
        loggingHelper.log("{}() - started", methodName);
        Object returnVal = joinPoint.proceed();
        loggingHelper.log("{}() - ended", methodName);

        return returnVal;
    }
}