dotnet / dotnet/aspnetcore

Slow model binding on first requests

Open
#52,861 4 comments 0 reactions 0 assignees View on GitHub
area-mvc Needs: Attention :wave:
Dominant language
C#
Stars
38.4k
Forks
10.9k
Avg merge
2d 5h
Merged PRs (30d)
276

Description

I'm trying to deal with 'cold start' issues in my Web API .NET 6 project. There is one particular issue I have difficulties with. Request's Json body deserialization and model binding are painfully slow each time some model is received for the first time after app launch. Issue occurs with any DTO model and it's especially noticeable with (reasonably) large models.
It may take up to 100-150ms to perform deserialization and model binding, which is too much. When some DTO model is received for the second time, it takes 1-2ms, which is great. Surely I understand that some compilation takes place during first request and some cache is used during subsequent ones, but still users are complaining and I really want to somehow reduce time spent on model binding during first requests.
I tried using source generator as I believed that this is exactly the feature created to deal with this issue, but it didn't provide any difference (I checked in debug that generated classes are actually being used, so I don't believe I messed up with src gen configuration).
I also tried .NET 8, issue is still there.

I created a tiny repro project: https://github.com/alexander-lubinets/DeserializationLatencyInvestigation
Timestamps of debug logs for the first request are the following:
```
DEBUG 2023-12-17 17:23:33,128 Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder [7] - Attempting to bind parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel' ...
DEBUG 2023-12-17 17:23:33,130 Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinder [7] - Attempting to bind parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel' using the name '' in request data ...
DEBUG 2023-12-17 17:23:33,131 Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinder [7] - Selected input formatter 'Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonInputFormatter' for content type 'application/json'.
DEBUG 2023-12-17 17:23:33,158 Microsoft.AspNetCore.Server.Kestrel [7] - Connection id "0HMVV2GGOJG9N", Request id "0HMVV2GGOJG9N:00000001": started reading request body.
DEBUG 2023-12-17 17:23:33,158 Microsoft.AspNetCore.Server.Kestrel [7] - Connection id "0HMVV2GGOJG9N", Request id "0HMVV2GGOJG9N:00000001": done reading request body.
DEBUG 2023-12-17 17:23:33,190 Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonInputFormatter [7] - JSON input formatter succeeded, deserializing to type 'DeserializationLatencyInvestigation.TestModel'
DEBUG 2023-12-17 17:23:33,191 Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinder [7] - Done attempting to bind parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel'.
DEBUG 2023-12-17 17:23:33,191 Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder [7] - Done attempting to bind parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel'.
DEBUG 2023-12-17 17:23:33,191 Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder [7] - Attempting to validate the bound parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel' ...
DEBUG 2023-12-17 17:23:33,214 Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder [7] - Done attempting to validate the bound parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel'.
```
Same logs for the second request:
```
DEBUG 2023-12-17 17:23:33,569 Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder [9] - Attempting to bind parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel' ...
DEBUG 2023-12-17 17:23:33,570 Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinder [9] - Attempting to bind parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel' using the name '' in request data ...
DEBUG 2023-12-17 17:23:33,570 Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinder [9] - Selected input formatter 'Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonInputFormatter' for content type 'application/json'.
DEBUG 2023-12-17 17:23:33,570 Microsoft.AspNetCore.Server.Kestrel [9] - Connection id "0HMVV2GGOJG9N", Request id "0HMVV2GGOJG9N:00000003": started reading request body.
DEBUG 2023-12-17 17:23:33,570 Microsoft.AspNetCore.Server.Kestrel [9] - Connection id "0HMVV2GGOJG9N", Request id "0HMVV2GGOJG9N:00000003": done reading request body.
DEBUG 2023-12-17 17:23:33,571 Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonInputFormatter [9] - JSON input formatter succeeded, deserializing to type 'DeserializationLatencyInvestigation.TestModel'
DEBUG 2023-12-17 17:23:33,571 Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinder [9] - Done attempting to bind parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel'.
DEBUG 2023-12-17 17:23:33,571 Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder [9] - Done attempting to bind parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel'.
DEBUG 2023-12-17 17:23:33,571 Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder [9] - Attempting to validate the bound parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel' ...
DEBUG 2023-12-17 17:23:33,571 Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder [9] - Done attempting to validate the bound parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel'.
```
The difference is enormous. Out of curiosity I tried performing deserialization manually in code on application startup and received the following results while processing first request:
```
DEBUG 2023-12-17 17:36:04,644 Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder [9] - Attempting to bind parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel' ...
DEBUG 2023-12-17 17:36:04,645 Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinder [9] - Attempting to bind parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel' using the name '' in request data ...
DEBUG 2023-12-17 17:36:04,646 Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinder [9] - Selected input formatter 'Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonInputFormatter' for content type 'application/json'.
DEBUG 2023-12-17 17:36:04,649 Microsoft.AspNetCore.Server.Kestrel [9] - Connection id "0HMVV2NGNK4B3", Request id "0HMVV2NGNK4B3:00000001": started reading request body.
DEBUG 2023-12-17 17:36:04,649 Microsoft.AspNetCore.Server.Kestrel [9] - Connection id "0HMVV2NGNK4B3", Request id "0HMVV2NGNK4B3:00000001": done reading request body.
DEBUG 2023-12-17 17:36:04,674 Microsoft.AspNetCore.Mvc.Formatters.SystemTextJsonInputFormatter [9] - JSON input formatter succeeded, deserializing to type 'DeserializationLatencyInvestigation.TestModel'
DEBUG 2023-12-17 17:36:04,675 Microsoft.AspNetCore.Mvc.ModelBinding.Binders.BodyModelBinder [9] - Done attempting to bind parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel'.
DEBUG 2023-12-17 17:36:04,675 Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder [9] - Done attempting to bind parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel'.
DEBUG 2023-12-17 17:36:04,675 Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder [9] - Attempting to validate the bound parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel' ...
DEBUG 2023-12-17 17:36:04,692 Microsoft.AspNetCore.Mvc.ModelBinding.ParameterBinder [9] - Done attempting to validate the bound parameter 'model' of type 'DeserializationLatencyInvestigation.TestModel'.
```
Obviously better, but far from perfect. Anyway, my real project has hundreds of endpoints and DTOs, so calling their deserialization on app startup is not an option.
So, what are your thoughts? Is there anything that can be done with this issue?

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.