Capture long running method execution in Spring Boot using annotation

  • |
  • 21 November 2023

It is crucial to capture long running method execution in your application (whether it is an API or traditional mvc application). You should also capture the method’s parameters to analyze what was wrong in your services, repositories or controller. Fortunately, using AOP we can create our own annotation to capture long running methods in spring boot. For instance we can log the method “if running time is longer than 5 seconds”.

To find out method execution time we can use Around advice:

You can check my notes about AOP (around advice) from this link

Let’s implement the specific annotation to capture long running method execution.

If you only need to see the code, here is the github link

Create the annotation

In our example, I will create an annotation called LongRunningExecution annotation class:

@Target({ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
@Documented
public @interface LongRunningExecution {
    
    boolean request() default false;
    
    boolean response() default false;
    
    long maxExecutionTime() default -1L;
}
  • request: mark as true if you want to log method’s request parameters
  • response: mark as true if you want to log method’s response
  • maxExecutionTime: set your execution time otherwise annotation will log the all calls for the method.

Create aspect for the annotation

I believe, the code is self-explanatory:

@Aspect
@Component
public class LongRunningExecutionAspect {

    private Logger logger(JoinPoint joinPoint) {
        return LoggerFactory.getLogger(joinPoint.getSignature().getDeclaringTypeName());
    }

    @Around("@annotation(LongRunningExecution)")
    public Object logMethod(ProceedingJoinPoint joinPoint) throws Throwable {
        Logger log = logger(joinPoint);

        MethodSignature signature = (MethodSignature) joinPoint.getSignature();
        Method method = joinPoint.getTarget()
                .getClass()
                .getMethod(signature.getMethod().getName(), signature.getMethod().getParameterTypes());
        LongRunningExecution longRunningExecution = method.getAnnotation(LongRunningExecution.class);

        boolean isRequestLogging = Objects.nonNull(longRunningExecution) && longRunningExecution.request();
        boolean isResponseLogging = Objects.nonNull(longRunningExecution) && longRunningExecution.response();
        boolean isMaxExecutionTimeFilter = Objects.nonNull(longRunningExecution) && longRunningExecution.maxExecutionTime() > -1L;

        String methodPath = joinPoint.getSignature().getDeclaringTypeName() + "#" + joinPoint.getSignature().getName();

        long start = System.currentTimeMillis();
        Object result = joinPoint.proceed();
        long end = System.currentTimeMillis();
        final long methodExecutionTimeInMs = end - start;

        if (isMaxExecutionTimeFilter) {
            if (methodExecutionTimeInMs > longRunningExecution.maxExecutionTime()) {
                if (isRequestLogging) {
                    log.info("LongRunningExecution: {} - Request: {} - Response time {} ms - Expected Response time {} ms", methodPath, joinPoint.getArgs(), methodExecutionTimeInMs, longRunningExecution.maxExecutionTime());
                }

                if (isResponseLogging) {
                    log.info("LongRunningExecution: {} - Response: {} - Response time {} ms - Expected Response time {} ms", methodPath, result, methodExecutionTimeInMs, longRunningExecution.maxExecutionTime());
                }
            }
        } else {
            if (isRequestLogging) {
                log.info("LongRunningExecution: {} - Request: {} - Response time {} ms", methodPath, joinPoint.getArgs(), methodExecutionTimeInMs);
            }

            if (isResponseLogging) {
                log.info("LongRunningExecution: {} - Response: {} - Response time {} ms", methodPath, result, methodExecutionTimeInMs);
            }
        }
        return result;
     }
}

Right now, the only thing we need to do add this annotation to our methods(methods in which spring aware of). Here are the some examples:

@RestController
public class DummyController {

    @GetMapping("/every-request")
    @LongRunningExecution(request = true)
    public String logEveryRequest(@RequestParam(name = "dummy") String test) {
        // LongRunningExecution will log the every request for the method call
        return "log-every-request";
    }

    @GetMapping("/every-request-response")
    @LongRunningExecution(request = true, response = true)
    public String logEveryRequestAndResponse(@RequestParam(name = "dummy") String test) {
        // LongRunningExecution will log the every request & response for the method call
        return "log-every-request-response";
    }

    @GetMapping("/every-request-response-execution-time")
    @LongRunningExecution(request = true, response = true, maxExecutionTime = 5000)
    public String logEveryRequestAndResponseForMethodExecution() throws InterruptedException {
        // LongRunningExecution will log the every request & response if the method execution time is longer than 5 seconds
        Thread.sleep(5001);
        return "log-every-request-response-execution-time";
    }
}

Let’s send the following curl requests:

$ curl -X GET http://localhost:8080/every-request?dummy=test-value

Then aspect print the following log(s):

INFO 125448 --- [nio-8080-exec-1] c.m.c.controller.DummyController         : LongRunningExecution: com.mehmetozanguven.capturelongrunningmethod.controller.DummyController#logEveryRequest - Request: [test-value] - Response time 0 ms

$ curl -X GET http://localhost:8080/every-request-response?dummy=test-value

Then aspect print the following log(s):

INFO 125630 --- [nio-8080-exec-1] c.m.c.controller.DummyController         : LongRunningExecution: com.mehmetozanguven.capturelongrunningmethod.controller.DummyController#logEveryRequestAndResponse - Request: [test-value] - Response time 0 ms
INFO 125630 --- [nio-8080-exec-1] c.m.c.controller.DummyController         : LongRunningExecution: com.mehmetozanguven.capturelongrunningmethod.controller.DummyController#logEveryRequestAndResponse - Response: log-every-request-response - Response time 0 ms

$ curl -X GET http://localhost:8080/every-request-response-execution-time

INFO 125791 --- [nio-8080-exec-1] c.m.c.controller.DummyController         : LongRunningExecution: com.mehmetozanguven.capturelongrunningmethod.controller.DummyController#logEveryRequestAndResponseForMethodExecution - Request: [] - Response time 5001 ms - Expected Response time 5000 ms
INFO 125791 --- [nio-8080-exec-1] c.m.c.controller.DummyController         : LongRunningExecution: com.mehmetozanguven.capturelongrunningmethod.controller.DummyController#logEveryRequestAndResponseForMethodExecution - Response: log-every-request-response-execution-time - Response time 5001 ms - Expected Response time 5000 ms

That’s it. With this simple Around advice solution you can log the specific method execution in your Spring boot application. You can also customize the logMethod for your needs.

You May Also Like