search

dotnet / aspnetcore

ASP.NET Core is a cross-platform .NET framework for building modern cloud-based web applications on Windows, Mac, or Linux.
https://asp.net
MIT License
35.06k stars 9.9k forks source link

Slow model binding on first requests #52861

Open alexander-lubinets opened 8 months ago

alexander-lubinets commented 8 months ago

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?

captainsafia commented 8 months ago

@alexander-lubinets Thanks for reporting this issue!

Where you able to do any profiling to identify what the delta is between the first time the request is sent and the second? I'm particularly surprised that using the source generator didn't show any benefit. It might indicate that the issue is coming from a different component.

ghost commented 8 months ago

Hi @alexander-lubinets. We have added the "Needs: Author Feedback" label to this issue, which indicates that we have an open question for you before we can take further action. This issue will be closed automatically in 7 days if we do not hear back from you by then - please feel free to re-open it if you come back to this issue after that time.

ghost commented 8 months ago

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment. If it is closed, feel free to comment when you are able to provide the additional information and we will re-investigate.

See our Issue Management Policies for more information.

alexander-lubinets commented 8 months ago

@captainsafia Thanks for reply! I've taken multiple snapshots using dotTrace, but I'm not really sure what exactly am I looking for. At first I thought that it's all about jit compilation, but I'm not so sure anymore as System Code and String subsystems are taking their time as well. Perhaps you are more experienced in reading snapshots, so I attached all of them. If I'm taking them in a wrong way maybe you could replicate the issue using repo I mentioned in my original post. I removed response serialization, swagger and debug logs in my repo to make sure they are not making things overcomplicated. I also tried performing request to another endpoint before profiling to make sure that some initial jit compilation is not taken into account as I don't really care about it. Btw, model binding still takes ~50ms if I send request to another endpoint first before taking time measurements. I also tried src gen again and profiled it. It always takes a few more milliseconds to process the request with src gen, which seems strange. I added another branch to my repo 'src-gen' to show how do I enable it, maybe I'm doing it the wrong way: https://github.com/alexander-lubinets/DeserializationLatencyInvestigation/tree/src-gen original snapshots.zip src gen snapshots.zip