Spring Boot : Logging Execution Time

Create a Simple Spring Boot App.

As a pre-requisite, we need to have a basic microservice with few endpoints.

In the earlier post Spring Boot JPA Crud Web App, we have implemented a simple microservice with basic CRUD functionality.

In this post, we shall see how to clock the execution time of a request within a microservice application.

Video guide of the process



 

For instance, we have few Controller or RestController classes, each having some RequestMapping methods. Now, how do we track the time taken by a specific endpoint for processing the request.

This can be easily achieved by registering a Filter that intercepts all the desired endpoints or url-patterns and clock the execution time.

Let’s register a OncePerRequestFilter through FilterRegistrationBean.

OncePerRequestFilter is an abstract class with one default method doFilterInternal, where we need to add our clock logic.

Any servlet filter that wraps the request, should be configured with an order that is less than or equal to 0, which is OrderedFilter.REQUEST_WRAPPER_FILTER_MAX_ORDER.

Configure the execution time logging filter bean as shown below.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
@Bean
public FilterRegistrationBean<OncePerRequestFilter> executionTimeLoggingFilter() {
  return new FilterRegistrationBean<OncePerRequestFilter>() {{
  setOrder(OrderedFilter.REQUEST_WRAPPER_FILTER_MAX_ORDER);
  setFilter(new OncePerRequestFilter() {

    @Override
    protected void doFilterInternal(HttpServletRequest req, HttpServletResponse res,
    FilterChain chain) throws ServletException, IOException {
        StopWatch watch = new StopWatch();
        watch.start();
        try {
          chain.doFilter(req, res);
        }finally {
          watch.stop();
          log.info("REQUEST: {} completed within {} ms",
                  getUriWithMethodAndQuery(req), watch.getTotalTimeMillis());
        }
      }

      private String getUriWithMethodAndQuery(HttpServletRequest req) {
        return req.getMethod() + ": " + req.getRequestURI() +
         (StringUtils.hasText(req.getQueryString()) ? "?" + req.getQueryString() : "");
      }
    });
  }};
}

With this, you are done with configuring the execution time logging filter bean.

Now, if you access any endpoints in your application, you will get output logging that includes the execution time as follows:

1
2
3
4
5
REQUEST: GET: /products completed within 174 ms
REQUEST: POST: /products completed within 8 ms
REQUEST: GET: /products completed within 4 ms
REQUEST: GET: /products/2 completed within 21 ms
REQUEST: GET: /products/2?alpha=beta&gamma=delta completed within 4 ms