Redis backplane for Asp.net core SignalR keeps getting timeout?

user_825920 0
Viewed 133

I have the following code to notify the SignalR clients using Redis (AWS Elasticache) backplane. It keeps getting timeout when groups have more than two values. What caused the timeout?

await Task.WhenAll(groups.Select(g => hubContext.Clients(g).SendAsync("DataUpdated", notification, ctoken)));

Here is one of the exception message,

Unhandled exception. StackExchange.Redis.RedisTimeoutException: Timeout awaiting response (outbound=0KiB, inbound=53KiB, 1009ms elapsed, timeout is 1000ms), command=PUBLISH, next: PUBLISH xyz, inst: 0, qu: 0, qs: 1, aw: False, rs: ReadAsync, ws: Idle, in: 33, serverEndpoint: clustercfg......use1.cache.amazonaws.com:6379, mc: 1/1/0, mgr: 10 of 10 available, clientName: myclient-..., IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=4,Free=32763,Min=1,Max=32767), v: 2.2.62.27853 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)

BTW, there is a timeout set to 1000ms. The exception shows the time is usually just a little bit over 1s. Where can I increase the value?

Jul 27, 2022 @ 16:49:14.693    Aborted (core dumped)
Jul 27, 2022 @ 16:49:13.806       at System.Threading.Tasks.Task.c.b__128_1(Object state)
Jul 27, 2022 @ 16:49:13.806       at System.Threading.Thread.StartCallback()
Jul 27, 2022 @ 16:49:13.806       at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
Jul 27, 2022 @ 16:49:13.806       at System.Threading.ThreadPoolWorkQueue.Dispatch()
Jul 27, 2022 @ 16:49:13.806       at Microsoft.AspNetCore.SignalR.StackExchangeRedis.RedisHubLifetimeManager`1.PublishAsync(String channel, Byte[] payload)
Jul 27, 2022 @ 16:49:13.806       at ....NotificationsHubProcessor.Notify(Family family, MessageNotification`1 notification, CancellationToken token) in /teamcity/work/.../NotificationsHubProcessor.cs:line 74
Jul 27, 2022 @ 16:49:13.806    Unhandled exception. StackExchange.Redis.RedisTimeoutException: Timeout awaiting response (outbound=0KiB, inbound=53KiB, 1000ms elapsed, timeout is 1000ms), command=PUBLISH, next: PUBLISH ....NotificationsHub:group:MWS:Groups:Family:All, inst: 0, qu: 0, qs: 1, aw: False, rs: ReadAsync, ws: Idle, in: 33, serverEndpoint: clustercfg.xxx.use1.cache.amazonaws.com:6379, mc: 1/1/0, mgr: 10 of 10 available, clientName: ..1, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=4,Free=32763,Min=1,Max=32767), v: 2.2.62.27853 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
Jul 27, 2022 @ 16:49:13.806       at ....NotificationsHubProcessor.b__9_0(MessageNotification`1 x) in /teamcity/work/.../NotificationsHubProcessor.cs:line 40
Jul 27, 2022 @ 16:49:13.806       at System.Threading.QueueUserWorkItemCallback.c.b__6_0(QueueUserWorkItemCallback quwi)
Jul 27, 2022 @ 16:49:13.806       at System.Threading.QueueUserWorkItemCallback.Execute()
Jul 27, 2022 @ 16:49:13.806       at ....NotificationsHubProcessor.Process(MessageNotification`1 notification, CancellationToken token) in /teamcity/work/.../NotificationsHubProcessor.cs:line 81
 
Jul 27, 2022 @ 16:45:04.163    Aborted (core dumped)
Jul 27, 2022 @ 16:45:02.494       at ....NotificationsHubProcessor.b__9_0(MessageNotification`1 x) in /teamcity/work/.../NotificationsHubProcessor.cs:line 40
Jul 27, 2022 @ 16:45:02.494       at ....NotificationsHubProcessor.Process(MessageNotification`1 notification, CancellationToken token) in /teamcity/work/.../NotificationsHubProcessor.cs:line 81
Jul 27, 2022 @ 16:45:02.494       at System.Threading.Tasks.Task.c.b__128_1(Object state)
Jul 27, 2022 @ 16:45:02.494       at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
Jul 27, 2022 @ 16:45:02.494       at System.Threading.QueueUserWorkItemCallback.c.b__6_0(QueueUserWorkItemCallback quwi)
Jul 27, 2022 @ 16:45:02.494       at System.Threading.QueueUserWorkItemCallback.Execute()
Jul 27, 2022 @ 16:45:02.494       at ....NotificationsHubProcessor.Notify(Family family, MessageNotification`1 notification, CancellationToken token) in /teamcity/work/.../NotificationsHubProcessor.cs:line 74
Jul 27, 2022 @ 16:45:02.494    Unhandled exception. StackExchange.Redis.RedisTimeoutException: Timeout awaiting response (outbound=0KiB, inbound=0KiB, 1132ms elapsed, timeout is 1000ms), command=PUBLISH, next: PUBLISH ....NotificationsHub:group:MWS:Groups:Family:M, inst: 0, qu: 2, qs: 1, aw: True, bw: Starting, rs: ReadAsync, ws: Flushing, in: 0, serverEndpoint: clustercfg.xxx.use1.cache.amazonaws.com:6379, mc: 1/1/0, mgr: 10 of 10 available, clientName: ..1, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=3,Free=32764,Min=1,Max=32767), v: 2.2.62.27853 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
Jul 27, 2022 @ 16:45:02.494       at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl_Awaited[T](ConnectionMultiplexer this, ValueTask`1 write, TaskCompletionSource`1 tcs, Message message, ServerEndPoint server) in /_/src/StackExchange.Redis/ConnectionMultiplexer.cs:line 2778
Jul 27, 2022 @ 16:45:02.494       at System.Threading.ThreadPoolWorkQueue.Dispatch()
Jul 27, 2022 @ 16:45:02.494       at Microsoft.AspNetCore.SignalR.StackExchangeRedis.RedisHubLifetimeManager`1.PublishAsync(String channel, Byte[] payload)
     
Jul 27, 2022 @ 15:49:22.769    Aborted (core dumped)
Jul 27, 2022 @ 15:49:21.302    Unhandled exception. StackExchange.Redis.RedisTimeoutException: Timeout awaiting response (outbound=0KiB, inbound=0KiB, 1435ms elapsed, timeout is 1000ms), command=PUBLISH, next: PUBLISH ....NotificationsHub:group:MWS:Groups:Family:M, inst: 0, qu: 2, qs: 1, aw: True, bw: Starting, rs: ReadAsync, ws: Flushing, in: 0, serverEndpoint: tre...-0009-001.xxx.use1.cache.amazonaws.com:6379, mc: 1/1/0, mgr: 10 of 10 available, clientName: ..2, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=3,Free=32764,Min=1,Max=32767), v: 2.2.62.27853 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
Jul 27, 2022 @ 15:49:21.302       at System.Threading.ThreadPoolWorkQueue.Dispatch()
Jul 27, 2022 @ 15:49:21.302       at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
Jul 27, 2022 @ 15:49:21.302       at ....NotificationsHubProcessor.Process(MessageNotification`1 notification, CancellationToken token) in /teamcity/work/.../NotificationsHubProcessor.cs:line 81
Jul 27, 2022 @ 15:49:21.302       at ....NotificationsHubProcessor.b__9_0(MessageNotification`1 x) in /teamcity/work/.../NotificationsHubProcessor.cs:line 40
Jul 27, 2022 @ 15:49:21.302       at System.Threading.Tasks.Task.c.b__128_1(Object state)
Jul 27, 2022 @ 15:49:21.302       at Microsoft.AspNetCore.SignalR.StackExchangeRedis.RedisHubLifetimeManager`1.PublishAsync(String channel, Byte[] payload)
Jul 27, 2022 @ 15:49:21.302       at System.Threading.QueueUserWorkItemCallback.Execute()
Jul 27, 2022 @ 15:49:21.302       at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl_Awaited[T](ConnectionMultiplexer this, ValueTask`1 write, TaskCompletionSource`1 tcs, Message message, ServerEndPoint server) in /_/src/StackExchange.Redis/ConnectionMultiplexer.cs:line 2778
Jul 27, 2022 @ 15:49:21.302       at ....NotificationsHubProcessor.Notify(Family family, MessageNotification`1 notification, CancellationToken token) in /teamcity/work/.../NotificationsHubProcessor.cs:line 74
Jul 27, 2022 @ 15:49:21.302       at System.Threading.QueueUserWorkItemCallback.c.b__6_0(QueueUserWorkItemCallback quwi)
signalr redis c#
1 Answers

The error explained

The root cause of the error is that it took longer than 1 second from the time the command was queued by StackExchange.Redis (the underlying redis provider that SignalR leans on here) to execute.

Why it happened

Why that happened can be a trickier question to answer, there isn't anything that jumps out at me given the text of the error, you have one operation that's been sent awaiting a response.

Some things it could be:

PUBLISH is an operation with linear complexity:

O(N+M) where N is the number of clients subscribed to the receiving channel and M is the total number of subscribed patterns (by any client).

So if you have many subscribed clients, each publish has to service all of them - which can be expensive. Also if there is a lot of other clients publishing or otherwise occupying your Redis Server, that can cause its own form of contention, blocking out this client's attempts to publish. This is pretty unlikely as redis tend to be super fast

Diagnosing

You can check to see what the traffic to your redis cluster looks like, if it looks like it's getting a ton of traffic maybe it really is locking up. More likely you are going to want to check the redis slowlog run a SLOWLOG GET against Redis, that will tell you if there are any obscenely long running commands.

Work around

To answer your last question, you can expand the allowed timeout by setting the asyncTimeout configuration option either in the connection string, or in the ConfigurationOptions (whatever you are doing to setup Redis)

user_72993450
Related