Does spring sometimes do some slow processes before and after controller method execution?

12/10/2020

I have a spring boot application running in a k8s environment.

When I was doing some tests to see how our app handles multiple request I have noticed that the application is losing some time before and after controller method execution. The application has some filters in place which are executing before and after controller method execution, but they aren't doing anything heavy, just reading some information from requests and removing some cached strings.

I have tracing setup so I can track the executions of certain parts of the application, mostly external calls, but for testing purposes I added tracing in additional parts. Trace root span is started in a filter which sits at the top of the filter chain.

You can see the weird behaviour in the image of traces bellow. In red I have marked spans which represent the controller methods, in black I have marked spans which represent spans of last two filters which are placed at the end of the filter chain.

In this image we can see that after taas_tenant_support_check fitler, which is second from last in the filter chain finished it's execution, controller method execution started 50ms later.

In this image we can see that taas_remove_bo_user_context filter, which is last in the filter chain, was executed at around 80ms later after controller method finished executing.

This behaviour was only captured while the application is running in k8s environment, on my local machine under the same load (which is currently just 50 parallel requests) this never happens.

Pod in which our application is running uses maximum of 1 CPU and 2GB of memory.

I have also ran an application on my local machine inside a docker container with similar resource restrictions, but the weird behaviour wasn't recorded.

Trace spans are exported in batches and that exporter is running in a separate thread from the main application and I don't think that this is slowing us down.

With debugger I went through the spring's source code to see what is going on before and after a controller method gets executed, but I haven't found anything that could cause this behaviour.

Does anyone have an idea what might be going on here?

-- Aleksandar Kojic
java
kubernetes
spring

0 Answers