Performance Issue Report - Azure App Service S1 Plan - abp.io v7.3.0

[plukic]

Description

I'm encountering a significant performance issue with our application hosted on Azure App Service using the S1 Plan. The problem specifically affects the first HTTP request after the app starts up. During this initial request, there's a noticeable delay, ranging from 9 to 15 seconds, which makes the application unresponsive.

Configuration

• .NET Version: .NET 7.0
• OS Version: Windows
• Architecture: x64
• Machine Specs: Azure App Service S1 Plan

Regression?

I'm unsure if this issue existed in previous builds or releases, as it's my first encounter with this problem.

Data

I've used MiniProfiler to profile the request execution, and here are the key findings:

• Time to reach the controller and method: Approximately 14,870 milliseconds.
• Time for business logic and database interactions: Only a few milliseconds.

Analysis

Based on the profiling results, it seems that the delay primarily occurs before the application's business logic and database interactions. It's not related to specific business logic or database queries within our code. The issue appears to be concentrated on the initial startup process.

I'm seeking assistance to identify the root cause of this performance problem and potential solutions to mitigate it. Any guidance or suggestions to improve the startup performance would be greatly appreciated.

[maliming]

hi You can enable Debug logs to see what's happened.

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    .Enrich.FromLogContext()
    .WriteTo.Async(c => c.File("Logs/logs.txt"))
    .WriteTo.Async(c => c.Console())
    .CreateLogger();

[plukic]

Update - Local Testing Results

I've conducted some local testing of our application to further investigate the performance issue. It appears that the delay is consistently associated with the initialization of controllers when the method is executed for the first time.

Here's an example log entry illustrating the delay:

2023-08-30 10:52:49.140 +02:00 [DBG] Executing controller factory for controller MyProject.Controllers.MyController (MyProject.HttpApi) and 2023-08-30 10:52:51.649 +02:00 [DBG] Executed controller factory for controller MyProject.Controllers.MyController (MyProject.HttpApi)

The time gap between these two log entries is approximately 2509 milliseconds, which accounts for a significant portion (99%) of the total request time.

To provide more context and facilitate troubleshooting, I've pasted the full log file bellow Please review the log file for any additional insights or patterns that could help identify the root cause of this initialization delay.

Any guidance or suggestions on how to address this controller initialization delay would be greatly appreciated. Thank you for your continued assistance in resolving this performance problem.

Here bellow is the full log file: 2023-08-30 10:52:49.130 +02:00 [INF] Request starting HTTP/2 GET https://localhost:44351/api/my-method - - 2023-08-30 10:52:49.131 +02:00 [DBG] The request path /api/my-method does not match a supported file type 2023-08-30 10:52:49.134 +02:00 [DBG] 1 candidate(s) found for the request path '/api/my-method' 2023-08-30 10:52:49.134 +02:00 [DBG] Endpoint 'MyProject.Controllers.MyController.MyMethod (MyProject.HttpApi)' with route pattern 'api/my-method' is valid for the request path '/api/my-method' 2023-08-30 10:52:49.134 +02:00 [DBG] Request matched endpoint 'MyProject.Controllers.MyController.MyMethod (MyProject.HttpApi)' 2023-08-30 10:52:49.134 +02:00 [DBG] The event OpenIddict.Validation.OpenIddictValidationEvents+ProcessRequestContext was successfully processed by OpenIddict.Validation.AspNetCore.OpenIddictValidationAspNetCoreHandlers+ResolveRequestUri. 2023-08-30 10:52:49.135 +02:00 [DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessRequestContext was successfully processed by OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlers+ResolveRequestUri. 2023-08-30 10:52:49.135 +02:00 [DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessRequestContext was successfully processed by OpenIddict.Server.OpenIddictServerHandlers+InferEndpointType. 2023-08-30 10:52:49.135 +02:00 [DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessRequestContext was successfully processed by OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlers+ValidateTransportSecurityRequirement. 2023-08-30 10:52:49.135 +02:00 [DBG] The event OpenIddict.Server.OpenIddictServerEvents+ProcessRequestContext was successfully processed by OpenIddict.Server.AspNetCore.OpenIddictServerAspNetCoreHandlers+ValidateHostHeader. 2023-08-30 10:52:49.136 +02:00 [DBG] AuthenticationScheme: Identity.Application was successfully authenticated. 2023-08-30 10:52:49.136 +02:00 [DBG] Authorization was successful. 2023-08-30 10:52:49.136 +02:00 [DBG] Static files was skipped as the request already matched an endpoint. 2023-08-30 10:52:49.137 +02:00 [INF] Executing endpoint 'MyProject.Controllers.MyController.MyMethod (MyProject.HttpApi)' 2023-08-30 10:52:49.139 +02:00 [INF] Route matched with {controller = "MyController", action = "MyMethod", area = "", page = ""}. Executing controller action with signature System.Threading.Tasks.Task1[Microsoft.AspNetCore.Mvc.ActionResult1[MyProject.MyResponseDto]] MyMethod() on controller MyProject.Controllers.MyController (MyProject.HttpApi). 2023-08-30 10:52:49.139 +02:00 [DBG] Execution plan of authorization filters (in the following order): ["Volo.Abp.AspNetCore.Mvc.AntiForgery.AbpAutoValidateAntiforgeryTokenAuthorizationFilter"] 2023-08-30 10:52:49.139 +02:00 [DBG] Execution plan of resource filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter"] 2023-08-30 10:52:49.139 +02:00 [DBG] Execution plan of action filters (in the following order): ["Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter (Order: -3000)","Volo.Abp.AspNetCore.Mvc.GlobalFeatures.GlobalFeatureActionFilter","Volo.Abp.AspNetCore.Mvc.Auditing.AbpAuditActionFilter","Volo.Abp.AspNetCore.Mvc.Response.AbpNoContentActionFilter","Volo.Abp.AspNetCore.Mvc.Features.AbpFeatureActionFilter","Volo.Abp.AspNetCore.Mvc.Validation.AbpValidationActionFilter","Volo.Abp.AspNetCore.Mvc.Uow.AbpUowActionFilter"] 2023-08-30 10:52:49.139 +02:00 [DBG] Execution plan of exception filters (in the following order): ["Volo.Abp.AspNetCore.Mvc.ExceptionHandling.AbpExceptionFilter"] 2023-08-30 10:52:49.139 +02:00 [DBG] Execution plan of result filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter","Microsoft.AspNetCore.Mvc.Infrastructure.ClientErrorResultFilter (Order: -2000)"] 2023-08-30 10:52:49.140 +02:00 [DBG] Executing controller factory for controller MyProject.Controllers.MyController (MyProject.HttpApi) 2023-08-30 10:52:50.622 +02:00 [INF] Request starting HTTP/2 GET https://localhost:44351/MyProject-profiler/results-list?last-id=a4637446-709e-48df-93f3-7d0c49de68e5 application/json - 2023-08-30 10:52:50.623 +02:00 [INF] Request finished HTTP/2 GET https://localhost:44351/MyProject-profiler/results-list?last-id=a4637446-709e-48df-93f3-7d0c49de68e5 application/json - - 200 6849 - 0.3556ms 2023-08-30 10:52:51.649 +02:00 [DBG] Executed controller factory for controller MyProject.Controllers.MyController (MyProject.HttpApi) 2023-08-30 10:52:51.650 +02:00 [INF] Executing action method MyProject.Controllers.MyController.MyMethod (MyProject.HttpApi) - Validation state: "Valid" 2023-08-30 10:52:51.678 +02:00 [DBG] Entity Framework Core 7.0.1 initialized 'MyProjectDbContext' using provider 'Microsoft.EntityFrameworkCore.SqlServer:7.0.1' with options: QuerySplittingBehavior=SplitQuery

[leonkosak]

@plukic, if you create empty API project in Visual Studio and deploy it to this Azure S1 plan - how many seconds is the execution time for the first request on basic controller method?

[maliming]

hi

I've conducted some local testing of our application to further investigate the performance issue.

Can you test the template project with your steps? also, share your steps.

[plukic]

IRepository Performance Investigation

Description: Okay, I've conducted further tests to pinpoint the root cause of the performance issue. It appears that the delay is indeed related to the usage of IRepository. Here's what I found:

I created a test controller where I injected IRepository for ABP.IO tables like IdentityUser, IdentityRole, etc. It took around 800ms just to construct this class.

Additionally, I tested this in my project where I have more than 35 tables, and I created a test service where I injected all these tables as IRepository. It took around 15-20 seconds to resolve all these dependencies. I'm now confident that the issue is directly tied to the usage of IRepository.

To confirm this, I injected an equivalent number of IDistributedCache instances, and it only took around 30-100ms to resolve that constructor with the same number of injections. This suggests that it's not a general issue with resolving dependencies but specifically an issue with resolving IRepository.

This discovery sheds light on the problem, and I believe addressing the performance of IRepository could be the key to improving controller factory performance.

I'm open to any suggestions or insights on how to optimize or mitigate this issue. Thank you for your assistance in tackling this problem.

Test code: MiniProfiler

[maliming]

Thanks @plukic

I tested this in my project where I have more than 35 tables, and I created a test service where I injected all these tables as IRepository. It took around 15-20 seconds to resolve all these dependencies.

Dependency injection can affect performance in some cases if you have too many services. You can use LazyServiceProvider to resolve services on demand instead of injecting all in the constructor.

[leonkosak]

@maliming what do you think about page in documentation where best practices and concepts would be gathered and linked to other pages in documentation. Let's say entity caching, external links (Microsoft,...) to write performant EF Core code,...?

[maliming]

@leonkosak This will be the best.

[leonkosak]

@maliming please create blank page in documentation (and in menu). Then send me a link to start writing for pull request. Thank you.

[maliming]

hi

Its better to create the md and add it to menu file in your PR.

[plukic]

Temporary Conclusion and Questions

I've made some significant progress in identifying the root causes of the performance issues we're encountering. Here's a summary of my findings and two questions I have:

Issue 1: Tracking with IReadOnlyRepository and IRepository With this version of ABP, it appears that both IReadOnlyRepository and IRepository are tracking all Entity Framework entities by default. This can be problematic, especially when dealing with large datasets during extensive calculations. It leads to memory and CPU spikes within the application. To address this issue, I've replaced each repository with my custom implementation that uses no tracking.

Issue 2: Initialization Time with Fluent API in Entity Framework Core I've been using Fluent API in Entity Framework Core, which greatly improves code readability by implementing IEntityTypeConfiguration<Entity> for each entity. However, I've noticed that the first query execution takes around 4-7 seconds to initialize everything, even if the application has been idle. This can be a significant delay, especially in time-critical production apps.

Now, I have two questions:

1. Is there a configuration option under IReadOnlyRepository that allows us to disable entity tracking by default? This could help address the memory and CPU spikes issue when loading a large number of rows.

2. Is there any way to speed up the initialization time for the first query when using Fluent API in Entity Framework Core? While it might be acceptable for the first query, it would be beneficial to minimize this startup time, especially in time-critical production environments.

I appreciate any insights or suggestions on these matters. Thank you for your continued assistance in resolving these performance challenges.

[maliming]

hi

1> We introduce a new feature on 8.0 https://github.com/abpframework/abp/blob/dev/docs/en/Repositories.md#read-only-repositories-behavior-in-entity-framework-core 2> No ideas.

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[developerMCSI]

hi

1> We introduce a new feature on 8.0 https://github.com/abpframework/abp/blob/dev/docs/en/Repositories.md#read-only-repositories-behavior-in-entity-framework-core 2> No ideas.

@hikalkan : do you have any ideas for point 2 or will this problem be mitigated with .net 8?

Thanks

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[RobertoFiocchiMCSI]

do you have any ideas for point 2 or will this problem be mitigated with .net 9?

[stale[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[RobertoFiocchiMCSI]

do you have any ideas for point 2 or will this problem be mitigated with .net 9?

Still no response, does anyone read old posts?