How to profile complex http request handling in Spring Boot?

Question

I have complex @RestController method, something like this:

@PostMapping("{id}")
@PreAuthorize("hasRole('ADMIN')")
@Transactional
public Response handleRequest(@PathVariable("id") long id, @RequestBody @Valid Request request) {
    return service.handleRequest(id, request);
}

Our request handling is quite slow so we want to check how much time is spent on particular request handling tasks. Unfortunately lot of things are done outside of my method, like:

• deserializing request
• validating
• permission checks
• starting and ending transaction
• serializing response

Is there way to simply measure all those parts? Maybe set of loggers that receive trace messages so I can pull timestamps at the end of each step?

The only way I see to do it now is change that method to accept HttpServletRequest and HttpServletResponse and do those parts inside method body. But that way I will lose lot of Spring Boot benefits.

Answer 1

you can also check a tuto for adding a custom metrics for actuator, but it seems a little bit complicate (but you'll you have to code your own metrics bean and inject it in your code, override objectMapper for mapping, etc... )

or maybe activate logging info on jackson,spring-security, javax.validation for checking the time in the log for each operation, but not very precise

Answer 2

what you exactly need is Java Thread Profiler which will tell you what is exactly going wrong and for it you can use any APM Tools and my favourite is GLOWROOT .which I have used in the similar scenarios to measure the performance of APIs and identify the slow traces which will clearly tell you which method is taking time and you can see the entire trace starting from method call to all the methods called inside and even identify slow queries if there are any . Hope this helps

Ths site: https://glowroot.org/

example trace :

https://demo.glowroot.org/transaction/thread-profile?transaction-type=Web&transaction-name=%2Fhot-sauces

Answer 3

There is no need to change the method to expect HttpServletRequest. You can use AspectJ

Using it, you can collect the time spent on each method and that analyze the data from it.

Create a methodTiming annotarion

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

In your Request, create a map that will keep all the methods and the time it took them:

  public class Request {
  private Map<String, Long> methodTimings = new TreeMap<String, Long>();

  public void addMethodTiming(String classAndMethodName, long executionTimeMillis) {
        Long value = methodTimings.get(classAndMethodName);
        if (value != null) {
            executionTimeMillis += value;
        }

        methodTimings.put(classAndMethodName, executionTimeMillis);
    }
  }

Than, create the Aspect class that will handle it:

@Aspect
@Component
public class MethodTimingAspect {
private static final String DOT = ".";

@Around("@annotation(MethodTiming)")
public Object timeAround(ProceedingJoinPoint joinPoint) throws Throwable  {
    Object result = null;

    StopWatch watch = new StopWatch();
    try {
        watch.start();
        result = joinPoint.proceed();
    } finally {
        watch.stop();
        long executionTime = watch.getLastTaskTimeMillis();

        String className = joinPoint.getTarget().getClass().getSimpleName();
        String methodName = joinPoint.getSignature().getName();
        String classAndMethodName = className + DOT + methodName;

        Object[] methodArgs = joinPoint.getArgs();
        if (methodArgs != null) {
            for (Object arg : methodArgs) {
                if (arg instanceof Request) {
                    // inject time back into Request
                    Request request = (Request) arg;
                    request.addMethodTiming(classAndMethodName, executionTime);

                    break;
                }
            }
        }

    }
    return result;
}

Finally, simply add the @MethodTiming on the methods you wish measure:

@MethodTiming
public Request handleRequest(Request request) {
// handle the Request
return request
}

Your request object will than have after the process something like

"methodTimings": {
    "RequestService.handleRequest": 2610,
    "AnotherRequestService.anotherMethod": 1351
}