Async / Redis Async problem?

grahamlaidler · March 12, 2024, 12:39pm

Hi, hope you can help. We are getting sporadic slowdowns on a .net 7.0 asp.net app using ServiceStack 6.8.0. These are intermittent, and having used dottrace, the “hot path” usually ends up down the AuthenticateAttribute subsequently calling async Redis code which eventually ends up in a WAIT state for up to 30 seconds.

Is using synchronous methods on Services acceptable or should all be converted to Async?
AuthenticateAttribute is now asynchronous, we are decorating synchronous methods with this attribute, this is supported according to docs, just want to double-check this is acceptable?
Below is an email from microsoft support suggesting that a 30 second operation taking place in ICacheClientAsync.GetAsync. Do you have any clue what could be causing this?

Any pointers gratefully received!

One of the longest operations is a 30 seconds operation, through ServiceStack.Redis!ICacheClientAsync.GetAsync à

Name First Last
||| | + module System.Private.CoreLib.il <<System.Private.CoreLib.il!Thread.StartCallback>> 48,426.180 80,289.140
||| | + module System.Net.Sockets.il <<System.Net.Sockets.il!System.Net.Sockets.SocketAsyncEventArgs+<>c.<.cctor>b__176_0(unsigned int32,unsigned int32,value class System.Threading.NativeOverlapped*)>> 48,426.180 80,289.140
||| | |+ module System.IO.Pipelines.il <<System.IO.Pipelines.il!InlineScheduler.Schedule>> 48,426.180 80,289.140
||| | | + module System.Private.CoreLib.il <<System.Private.CoreLib.il!ThreadPool.UnsafeQueueUserWorkItem>> 48,426.180 80,289.140
||| | | + module ntdll <<ntdll!EtwEventWriteTransfer>> 48,426.180 80,289.140
||| | | + module wow64 <<wow64!Wow64LdrpInitialize>> 48,426.180 80,289.140
||| | | + module wow64cpu <<wow64cpu!ServiceNoTurbo>> 48,426.180 80,289.140
||| | | + module wow64 <<wow64!Wow64SystemServiceEx>> 48,426.180 80,289.140
||| | | + module ntdll <<ntdll!ZwTraceEvent>> 48,426.180 80,289.140
||| | | + module Microsoft.AspNetCore.Hosting.il <<Microsoft.AspNetCore.Hosting.il!HostingApplication.ProcessRequestAsync>> 48,426.570 80,289.140
||| | | |+ module Microsoft.AspNetCore.HostFiltering.il <<Microsoft.AspNetCore.HostFiltering.il!HostFilteringMiddleware.Invoke>> 48,426.570 80,289.140
||| | | | + module Microsoft.AspNetCore.Http.Abstractions.il <<Microsoft.AspNetCore.Http.Abstractions.il!UsePathBaseMiddleware.Invoke>> 48,426.570 80,289.140
||| | | | + module Microsoft.AspNetCore.HttpOverrides.il <<Microsoft.AspNetCore.HttpOverrides.il!ForwardedHeadersMiddleware.Invoke>> 48,426.570 80,289.140
||| | | | |+ module Microsoft.AspNetCore.Server.IISIntegration.il <<Microsoft.AspNetCore.Server.IISIntegration.il!IISMiddleware.Invoke>> 48,426.570 80,289.140
||| | | | | + module Microsoft.AspNetCore.Http.Abstractions.il <<Microsoft.AspNetCore.Http.Abstractions.il!UsePathBaseMiddleware.Invoke>> 48,426.570 80,289.140
||| | | | | + module ServiceStack <<ServiceStack!AppHostBase.ProcessRequest>> 48,426.570 80,289.140
||| | | | | + module ServiceStack.Redis <<ServiceStack.Redis!ICacheClientAsync.GetAsync>> 50,161.414 80,289.140
||| | | | | |+ module System.Private.CoreLib.il <<System.Private.CoreLib.il!System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable`1+ConfiguredValueTaskAwaiter[System.__Canon].System.Runtime.CompilerServices.IStateMachineBoxAwareAwaiter.AwaitUnsafeOnCompleted(class System.Runtime.CompilerServices.IAsyncStateMachineBox)>> 50,161.555 54,312.527
||| | | | | ||+ module ntdll <<ntdll!EtwEventWriteTransfer>> 50,161.555 54,312.527
||| | | | | |+ module System.Net.Security.il <<System.Net.Security.il!SslStream.ReadAsync>> 50,161.482 80,289.140

EF Compilation operation, taking a couple of seconds à

Name First Last
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | |+ module Microsoft.AspNetCore.HostFiltering.il <<Microsoft.AspNetCore.HostFiltering.il!HostFilteringMiddleware.Invoke>> 119,148.679 121,417.676
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | + module Microsoft.AspNetCore.Http.Abstractions.il <<Microsoft.AspNetCore.Http.Abstractions.il!UsePathBaseMiddleware.Invoke>> 119,148.679 121,417.676
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | + module Microsoft.AspNetCore.HttpOverrides.il <<Microsoft.AspNetCore.HttpOverrides.il!ForwardedHeadersMiddleware.Invoke>> 119,148.679 121,417.676
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | + module Microsoft.AspNetCore.Server.IISIntegration.il <<Microsoft.AspNetCore.Server.IISIntegration.il!IISMiddleware.Invoke>> 119,148.679 121,417.676
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | + module Microsoft.AspNetCore.Http.Abstractions.il <<Microsoft.AspNetCore.Http.Abstractions.il!UsePathBaseMiddleware.Invoke>> 119,148.679 121,417.676
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | + module ServiceStack <<ServiceStack!AppHostBase.ProcessRequest>> 119,148.679 121,417.676
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | + module Assembly <<Anonymously Hosted DynamicMethods Assembly!dynamicClass.lambda_method614(pMT: 2E2FD4A8,class System.Object,class System.Object)>> 119,148.679 121,413.618
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | |+ module HarbourAssist.Api.Main.Api <<HarbourAssist.Api.Main.Api!PublicEmailApi.Post>> 119,148.679 121,413.618
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | | + module HarbourAssist.Core <<HarbourAssist.Core!EmailBusiness.Process>> 119,148.679 121,413.618
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | | |+ module Objects <<KellermanSoftware.Compare-NET-Objects!CompareLogic.Compare>> 119,179.621 121,397.173
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | | ||+ module System.Private.CoreLib.il <<System.Private.CoreLib.il!RuntimePropertyInfo.GetValue>> 119,179.621 121,340.619
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | | |||+ module HarbourAssist.Core <<HarbourAssist.Core!AttachableObject.get_Route>> 119,179.621 121,340.619
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | | ||||+ module System.Linq.il <<System.Linq.il!Enumerable.TryGetFirst>> 119,180.678 121,340.197
|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||| | | | |||||+ module HarbourAssist.Core <<HarbourAssist.Core!HarbourAssist.Infrastructure.Core.Entities.AttachableObject+<>c__DisplayClass13_0.<get_Route>b__0(class System.Type)>> 119,236.619 121,340.197
…

Another EF Compilation taking 4-5 seconds.

Name First Last
|||||||||||||||||| | + module ServiceStack <<ServiceStack!ServiceStack.AuthenticateAttribute+d__12.MoveNext()>> 75,675.206 79,964.653
|||||||||||||||||| | + module System.Private.CoreLib.il <<System.Private.CoreLib.il!Task.FinishContinuations>> 75,675.206 79,964.653
|||||||||||||||||| | + module ServiceStack <<ServiceStack!ServiceStack.ServiceStackHost+d__431.MoveNext()>> 75,675.206 79,964.653
|||||||||||||||||| | + module System.Private.CoreLib.il <<System.Private.CoreLib.il!Task.FinishContinuations>> 75,675.206 79,964.653
|||||||||||||||||| | + module ServiceStack <<ServiceStack!ServiceStack.ServiceStackHost+d__430.MoveNext()>> 75,675.206 79,964.653
|||||||||||||||||| | + module System.Private.CoreLib.il <<System.Private.CoreLib.il!Task.FinishContinuations>> 75,675.206 79,964.653
|||||||||||||||||| | + module ServiceStack <<ServiceStack!ServiceStack.Host.RestHandler+d__14.MoveNext()>> 75,675.206 79,964.653
|||||||||||||||||| | + module Assembly <<Anonymously Hosted DynamicMethods Assembly!dynamicClass.lambda_method613(pMT: 2E2FD4A8,class System.Object,class System.Object)>> 75,675.206 79,964.653
|||||||||||||||||| | + module HarbourAssist.Api.Main.Api <<HarbourAssist.Api.Main.Api!EmailApi.Get>> 75,675.206 79,964.653
|||||||||||||||||| | + module HarbourAssist.Core <<HarbourAssist.Core!EmailSnippetService.RenderAllSnippets>> 75,707.678 79,964.653
|||||||||||||||||| | |+ module Handlebars <<Handlebars!HandlebarsEnvironment.Compile>> 75,707.678 79,964.653
|||||||||||||||||| | ||+ module System.Linq.Expressions.il <<System.Linq.Expressions.il!System.Linq.Expressions.Expression`1[System.__Canon].Compile()>> 75,713.084 79,964.653
|||||||||||||||||| | |||+ module System.Private.CoreLib.il <<System.Private.CoreLib.il!DynamicMethod.CreateDelegate>> 75,713.084 79,964.653

8 seconds operation , for ServiceStack.Text!JsonSerializer.DeserializeFromString à
Name First Last
|||| + module ntdll <<ntdll!ZwTraceEvent>> 54,193.435 63,040.775
|||| + module Microsoft.AspNetCore.Hosting.il <<Microsoft.AspNetCore.Hosting.il!HostingApplication.ProcessRequestAsync>> 54,193.651 63,040.576
|||| |+ module Microsoft.AspNetCore.HostFiltering.il <<Microsoft.AspNetCore.HostFiltering.il!HostFilteringMiddleware.Invoke>> 54,193.651 63,040.576
|||| | + module Microsoft.AspNetCore.Http.Abstractions.il <<Microsoft.AspNetCore.Http.Abstractions.il!UsePathBaseMiddleware.Invoke>> 54,193.651 63,040.576
|||| | + module Microsoft.AspNetCore.HttpOverrides.il <<Microsoft.AspNetCore.HttpOverrides.il!ForwardedHeadersMiddleware.Invoke>> 54,193.651 63,040.568
|||| | |+ module Microsoft.AspNetCore.Server.IISIntegration.il <<Microsoft.AspNetCore.Server.IISIntegration.il!IISMiddleware.Invoke>> 54,193.651 63,040.568
|||| | | + module Microsoft.AspNetCore.Http.Abstractions.il <<Microsoft.AspNetCore.Http.Abstractions.il!UsePathBaseMiddleware.Invoke>> 54,193.651 63,040.568
|||| | | + module ServiceStack <<ServiceStack!AppHostBase.ProcessRequest>> 54,193.651 63,040.568
|||| | | + module ServiceStack.Redis <<ServiceStack.Redis!ICacheClientAsync.GetAsync>> 54,197.922 62,862.840
|||| | | |+ module System.Private.CoreLib.il <<System.Private.CoreLib.il!System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable1+ConfiguredValueTaskAwaiter[System.__Canon].System.Runtime.CompilerServices.IStateMachineBoxAwareAwaiter.AwaitUnsafeOnCompleted(class System.Runtime.CompilerServices.IAsyncStateMachineBox)>> 54,197.941 62,862.830 |||| | | ||+ module ntdll <<ntdll!EtwEventWriteTransfer>> 54,197.941 62,862.830 |||| | | || + module wow64 <<wow64!Wow64LdrpInitialize>> 54,197.941 62,862.830 |||| | | || + module wow64cpu <<wow64cpu!ServiceNoTurbo>> 54,197.941 62,862.830 |||| | | || + module wow64 <<wow64!Wow64SystemServiceEx>> 54,197.941 62,862.830 |||| | | || + module ntdll <<ntdll!ZwTraceEvent>> 54,197.941 62,862.830 |||| | | || + EventData SessionName AzureProfiler CLR Session 54,298.376 62,862.811 |||| | | || + module ServiceStack.Redis <<ServiceStack.Redis!ServiceStack.Redis.RedisClient+<>c__DisplayClass23_01+<b__0>d[System.__Canon].MoveNext()>> 54,203.416 62,862.780
|||| | | || |+ module ServiceStack.Text <<ServiceStack.Text!JsonSerializer.DeserializeFromString>> 54,203.416 62,862.780
…
…

mythz · March 12, 2024, 1:14pm

Async is preferred since it would require less threads which uses less resources and leads to less thread pool starvation.

That’s fine, everything else in ServiceStack request pipeline uses async non-blocking I/O by default, but that shouldn’t force your own code to use it.

The only thing I could think would cause this is if you’re using a PooledRedisClientManager which would block until there are other pooled clients available. If you are I would switch to RedisManagerPool where when the pool is full it would create clients outside of the pull instead of blocking.

grahamlaidler · March 12, 2024, 1:47pm

Hi, thanks for prompt response!

RedisConfig.DefaultMaxPoolSize = 500;
RedisConfig.DefaultRetryTimeout = 10;
 
container.Register<IRedisClientsManager>(c => new RedisManagerPool(connectionString)).ReusedWithin(ReuseScope.Hierarchy);

We’re have the above Funq registration - would registering it as IRedisClientsManagerAsync make any difference?

mythz · March 12, 2024, 5:55pm

No it wouldn’t make a difference as AppHost.GetRedisClientAsync() checks both registrations. It would force usage of IRedisClientsManagerAsync and prevent usage of IRedisClientsManager which wouldn’t be registered.

Note: Although we’re now recommending registering dependencies in ASP .NET Core IOC so they’re available in both ServiceStack and other ASP .NET Core classes outside of ServiceStack:

.ConfigureServices((context, services) => {
      var connectionString  = context.Configuration.GetConnectionString("Redis");
      services.AddSingleton<IRedisClientsManager>(
          new RedisManagerPool(connectionString));
})

grahamlaidler · March 18, 2024, 3:29pm

Thanks. We think it may be relating to our implementation of RequestFilters. Currently all are sync, they internally call IRedisClient (sync).

Should we:

a) Convert all to async and add them via appHost.GlobalRequestFiltersAsync.Add(xAsync)?
b) Add async version of all and add them to appHost.GlobalRequestFiltersAsync.Add(xAsync) and leave them in the GlobalRequestFilters.Add(x)?
c) Something else?

mythz · March 18, 2024, 8:20pm

If you think it’s due to using sync RequestFilters then changing them to use the async Request Filters would be the obvious solution.