Logging elapsed time of execution in SpringBoot rest API

Question

It could be a simple solution but I am unable to get it done. I need to log the overall execution time for my request in SpringBoot Rest API. Request always enters to MainController always and can exit from two places-

1. Main Restcontroller same method or
2. ExceptionHandlerController handler method

I have created one custom annotation and injecting it to both main Controller and ExceptionController methods and getting elapsed time for individual methods. So here is the problem. I need to add these individual times to calculate the total time which I don't want.

Is there any other way to log this information easily.

Aspect class:

@Aspect
@Component
public class PointsAspect {

    private final static Logger logger = LoggerFactory.getLogger(PointsAspect.class);

    @Around("@annotation(annotation)")
    public Object logMethod(final ProceedingJoinPoint proceedingJoinPoint, final LogAround annotation)
            throws Throwable {
        final long start = System.currentTimeMillis();
        Object obj;
        try {
            logger.debug("Starting...! Method Name - " +proceedingJoinPoint.getSignature().getName());
            obj = proceedingJoinPoint.proceed();
        } finally {
            logger.debug("Exiting...! Method Name - " +proceedingJoinPoint.getSignature().getName() +"Execution Time in Milliseconds:> "+ String.valueOf(System.currentTimeMillis()-start));
        }
        return obj;
    }
}

Marker Interface:

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

}

And this is how I am injecting it:

**ExceptionHandlerController.java**

@LogAround
@ExceptionHandler(HttpMessageNotReadableException.class)
public GenericFailureResponse missingRequestBodyException(HttpServletResponse response,
            HttpServletRequest request, Exception ex) throws IOException {
        GenericFailureResponse failureResponse =  new GenericFailureResponse();
        //TODO: exception logic
        return failureResponse;
}



**MainController.java**

@LogAround
 public String getTotalPoints(@RequestParam(required=true) long memberNo,
            HttpServletRequest httpServletRequest, HttpServletResponse httpServletResponse) {
        //TODO : some logic
        return "something";
 }

Answer 1

You can use a simple filter.

@Component
public class LogTimeFilter implements Filter {

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        long startTime = System.currentTimeMillis();
        chain.doFilter(request, response);
        long duration = System.currentTimeMillis() - startTime;
        System.out.println("Request take " + duration + " ms");
    }
}

Answer 2

I have solved it using annotation and advice.

First need to add these dependencies

org.springframework.boot spring-boot-starter-web org.springframework.boot spring-boot-starter-aop

then i create a annotation as follows

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

/**
 * Creator : Tanvir Chowdhury
 * Date    : 2023-02-23
 */
@Target(ElementType.METHOD)
@Retention(value = RetentionPolicy.RUNTIME)
public @interface TimeTraker {
}

then i write the time measuring logic in the advice class

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import org.springframework.util.StopWatch;

/**
 * Creator : Tanvir Chowdhury
 * Date    : 2023-02-23
 */


@Aspect
@Component
public class RequestResponseTimeTracker  {


    private static Logger logger = LoggerFactory.getLogger(RequestResponseTimeTracker.class);

    @Around("@annotation(com.reliantvalue.lake.security.TimeTraker)")
    public Object measureTime(ProceedingJoinPoint point) throws Throwable {
        StopWatch stopWatch = new StopWatch();
        stopWatch.start();
        Object object = point.proceed();
        stopWatch.stop();
        logger.debug("Execution Time taken by : " + point.getSignature().getName() + "() method is - "
                + stopWatch.getTotalTimeMillis() + " ms");
        return object;
    }
}

thats all. Now use the annotation TimeTracker on rest controller like this

@SneakyThrows
    @PostMapping
    @JsonView(View.Full.class)
    @TimeTraker
    public Loan createLoan(@CurrentUser User user,
                           @RequestParam(value = "type", required = false) String type,
                           @RequestParam(value = "wf", required = false) String wfId,
                           @RequestBody LoanCreateRequestDTO loanCreateRequest) {
}

the output will be something like this

2023-02-23 17:32:36,958 INFO  [http-nio-5000-exec-6] c.r.l.s.RequestResponseTimeTracker: Execution Time taken by : deleteLoan() method is - 3776 ms