RedisTimeoutException exception message question

[CDargis]

Hi. Using version 2.0. 495. I've seen this page and have found some great information. I have a question about some of the information in the timeout exception message. As an example:

StackExchange.Redis.RedisTimeoutException: Timeout awaiting response (15281ms elapsed, timeout is 15000ms), inst: 0, qs: 414, in: 65536, serverEndpoint: ***, mgr: 10 of 10 available, clientName: ***, IOCP: (Busy=1,Free=999,Min=2,Max=1000), WORKER: (Busy=68,Free=32699,Min=2,Max=32767)

I understand that Busy > Min = waiting 500ms for a new thread to get added to the pool. What I am wondering is why mgr: 10 of 10 available - shouldn't the mgr count read 0 of 10 available since we are in the global thread pool? In pretty much all of our timeout errors there are at least 9 of 10 available (and we have A LOT of timeouts). I've seen this with both worker and IOCP threads being > than the min.

[mgravell]

Without more context it is hard to know what is happening. On the surface, the custom pool seems to think it is idle. Whether that is right or not is complex - I should ensure that is visible in the log. The high "in" is concerning, though. I hope we haven't found a new way of stealing reader threads!

…

On Fri, 12 Oct 2018, 22:53 Chris Dargis, ***@***.***> wrote: Hi. Using running version 2.0. 495. I've seen this <https://github.com/StackExchange/StackExchange.Redis/blob/master/docs/Timeouts.md> page and have found some great information. I have a question about some of the information in the timeout exception message. As an example: StackExchange.Redis.RedisTimeoutException: Timeout awaiting response (15281ms elapsed, timeout is 15000ms), inst: 0, qs: 414, in: 65536, serverEndpoint: ***, mgr: 10 of 10 available, clientName: ***, IOCP: (Busy=1,Free=999,Min=2,Max=1000), WORKER: (Busy=68,Free=32699,Min=2,Max=32767) I understand that Busy > Min = waiting 500ms for a new thread to get added to the pool. What I am wondering is why mgr: 10 of 10 available - shouldn't the mgr count read 0 of 10 available since we are in the global thread pool? In pretty much all of our timeout errors there are at least 9 of 10 available. I've seen this with both worker and IOCP threads being > than the min. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#973>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AABDsMgq5ldZfvP8ntaCn5sAmtcg7g__ks5ukQ9YgaJpZM4XaPuR> .

[CDargis]

Thanks for the prompt response.

For context - we recently upgraded from 1.2 and have seen 10x more timeouts. We use redis to cache our NoSQL objects (which we can pull from Dynamo under the same load with no issues). The objects cached are around 200-300k. Some can be a little bigger. We now realize the recommendation is to have objects at 100k and we'll be making those changes. We use hashed objects for most of the objects that are larger and shoot for bucket sizes of 1000. I can say we experience these timeouts when bursts of parallel async work comes in (Task.WhenAll()). Previously we did not need to set min thread numbers but now we're setting them as high as 1000 to resolve these timeouts. With the min thread count this high we can get through the timeouts but everything is much more performant going straight to Dynamo ( we don't need to touch the min thread count for Dynamo)

EDIT: It is possible there are other contributing factors to our recent surge in timeouts such as change and size of our data.

Is there any more context I can give you?

Some follow-up questions:

1. does the above give you any more insight?
2. would you mind pointing me at the relevant code for why the custom pool would report idle?
3. the in number seems like a default buffer size which tells me 0 bytes read maybe? What are reader threads?

[CDargis]

Another error that may help provide insight here:

StackExchange.Redis.RedisConnectionException: SocketFailure on master.pp-app-cache.6koqgr.use1.cache.amazonaws.com:6379/Interactive, Idle, last: HGET, origin: ReadFromPipe, outstanding: 144, last-read: 930s ago, last-write: 29s ago, unanswered-write: 930s ago, keep-alive: 60s, state: ConnectedEstablished, mgr: 0 of 10 available, in: 0, last-heartbeat: 20s ago, last-mbeat: 4s ago, global: 0s ago, v: 2.0.513.63329 ---> System.IO.IOException: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host. ---> System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
at System.Net.Sockets.Socket.BeginReceive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags, AsyncCallback callback, Object state)
at System.Net.Sockets.NetworkStream.BeginRead(Byte[] buffer, Int32 offset, Int32 size, AsyncCallback callback, Object state)

This is the first I've seen the 0 of 10 available in our errors, but I think the most interesting here is:

last-read: 930s ago, last-write: 29s ago,

930 seconds is 15 minutes. No idea why the host would be shutting down the connection.

[danmml]

I'm having similar timeout issues with the > 2.0 libraries compared to 1.2 version. The issues seems to come from what looks like higher Server load/server side retries (it starts to fall apart for me around 2k connections, and 20% Server load from an Azure Redis C6 instance). The general errors I see are similar to the below example
Timeout awaiting response (15750ms elapsed, timeout is 15000ms), inst: 0, qs: 40162, in: 0, serverEndpoint: Unspecified/...:6380, mgr: 7 of 10 available, clientName: ..., IOCP: (Busy=1,Free=999,Min=512,Max=1000), WORKER: (Busy=52,Free=32715,Min=1024,Max=32767),

Based on this: qs numbers seem really high-- my understanding based on the documentation, is that these are outstanding requests that have not been processed. I'm trying to figure out how these numbers are so high, as based on my code, I don't think it allows creating more than 5k requests. Is there a way to clear out outstanding requests, or flush a connection under timeouts? I've looked through the source code, but it's not clear to me how the library clears out requests that have been "abandoned" by the client.

@mgravell : Is there a recommended setting for high loads for the 2.0 libraries? I'm experimenting with some different settings now, although I think the general consensus I'm coming to is that the retry/settings that worked for 1.2, don't seem to behave well for us with 2.0 libraries.

[vanderlei-dev]

I'm having the same error in a website only when a have peak access (more requests than my average).
Both IIS and Redis Server are large enough and the resources (network traffic, CPU and memory) are just fine.

I already increased the thread quantity in machine.config and even implemented a "connection pool" as described in https://stackexchange.github.io/StackExchange.Redis/Timeouts) but no luck with that.

Here its a sample of the errors:

Timeout performing GET   (5000ms), inst: 0, qs: 1, in: 0, 	 mgr: 10 of 10 available,  IOCP: (Busy=0,Free=2400,Min=1200,Max=2400), WORKER: (Busy=17,Free=2383,Min=1200,Max=2400), v: 2.0.513.63329
Timeout performing GET   (5000ms), inst: 0, qs: 1, in: 65536,mgr: 0 of 10 available,  IOCP: (Busy=1,Free=2399,Min=1200,Max=2400), WORKER: (Busy=19,Free=2381,Min=1200,Max=2400), v: 2.0.513.63329 
Timeout performing GET   (5000ms), inst: 0, qs: 1, in: 0, 	 mgr: 10 of 10 available,  IOCP: (Busy=0,Free=2400,Min=1200,Max=2400), WORKER: (Busy=17,Free=2383,Min=1200,Max=2400), v: 2.0.513.63329
Timeout performing GET   (5000ms), inst: 0, qs: 1, in: 8080, mgr: 9 of 10 available,  IOCP: (Busy=0,Free=2400,Min=1200,Max=2400), WORKER: (Busy=21,Free=2379,Min=1200,Max=2400), v: 2.0.513.63329 
Timeout performing GET   (5000ms), inst: 0, qs: 1, in: 0, 	 mgr: 6 of 10 available,  IOCP: (Busy=4,Free=2396,Min=1200,Max=2400), WORKER: (Busy=34,Free=2366,Min=1200,Max=2400), v: 2.0.513.63329 
Timeout performing HMSET (5000ms), inst: 0, qs: 1, in: 0, 	 mgr: 10 of 10 available,  IOCP: (Busy=0,Free=2400,Min=1200,Max=2400), WORKER: (Busy=7,Free=2393,Min=1200,Max=2400), v: 2.0.513.63329 
Timeout performing GET   (5000ms), inst: 0, qs: 1, in: 0, 	 mgr: 9 of 10 available,  IOCP: (Busy=0,Free=3200,Min=1600,Max=3200), WORKER: (Busy=11,Free=3189,Min=1600,Max=3200), v: 2.0.513.63329 
Timeout performing GET 	 (5000ms), inst: 0, qs: 1, in: 0, 	 mgr: 10 of 10 available,  IOCP: (Busy=0,Free=2400,Min=1200,Max=2400), WORKER: (Busy=11,Free=2389,Min=1200,Max=2400), v: 2.0.513.63329
Timeout performing HMSET (5000ms), inst: 0, qs: 2, in: 0, 	 mgr: 10 of 10 available,  IOCP: (Busy=0,Free=2400,Min=1200,Max=2400), WORKER: (Busy=12,Free=2388,Min=1200,Max=2400), v: 2.0.513.63329

I noticed there the "in" amount in one of the log messages (in: 65536) its exactly the same as @CDargis (!?). Thats mean something? Any ideias @mgravell ?

[CDargis]

@Vanderleipires

I've also implemented connection pooling that doesn't seem to help much. We have a typical cache-aside pattern with redis/dynamo.

What I noticed is that we experience the timeouts when large amounts of async work comes in (await Task.WhenAll()) and we were passing lots of tasks here sometimes. And these tasks spawn lots of other tasks that hit the cache and DB. Instead of passing all of the tasks at once I implemented parallel async extension to take in account the degree of parallelism. So instead of launching all of the tasks all at once with Task.WhenAll() we set the degree of parallelism to Environment.ProcessorCount. This definitely goes slower but it alleviates a lot of the timeouts. We've also stopped caching in a lot of spots. For the time being this is the solution we've gone with.

[hpk]

We are experiencing similar issues in v2. Our Redis is a pretty over-provisioned ElastiCache cluster. Workload is mostly cache-aside with small items (only a few KB at most).

I've noticed the errors come in three flavors. Here are some representative samples:

1. RedisTimeoutException:

StackExchange.Redis.RedisTimeoutException: Timeout awaiting response (5484ms elapsed, 
timeout is 5000ms), inst: 0, qs: 138, in: 0, serverEndpoint: 10.72.144.135:6379, mgr: 10 of 10
available, clientName: B4D107E329BC, PerfCounterHelperkeyHashSlot: 3602, IOCP:
(Busy=0,Free=1000,Min=150,Max=1000), WORKER: (Busy=13,Free=32754,Min=150,Max=32767),
v: 2.0.513.63329 (Please take a look at this article for some common client-side issues that can
cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)

2. RedisConnectionException: No connection is available to service this operation:

StackExchange.Redis.RedisConnectionException: No connection is available to service this
operation: HGETALL SR:reporter:500:d747d528-2b6b-465f-aa94-b9af4c1b705e; IOCP: 
(Busy=0,Free=1000,Min=200,Max=1000), WORKER: (Busy=11,Free=32756,Min=200,
Max=32767), Local-CPU: n/a

3. RedisConnectionException: SocketFailure:

StackExchange.Redis.RedisConnectionException: SocketFailure (ReadSocketError/TimedOut, 
last-recv: 5) on 10.72.144.135:6379/Interactive, Idle, last: INCR, origin: ReadFromPipe, 
outstanding: 323, last-read: 134942s ago, last-write: 0s ago, unanswered-write: 134942s 
ago, keep-alive: 10s, state: ConnectedEstablished, mgr: 9 of 10 available, in: 0, last-heartbeat: 
0s ago, last-mbeat: 0s ago, global: 0s ago, v: 2.0.513.63329 --->
System.Net.Sockets.SocketException: A connection attempt failed because the connected 
party did not properly respond after a period of time, or established connection failed 
because connected host has failed to respond

We have hundreds of containers in production all talking to the same ElastiCache cluster, but these connection errors only occur on one host at a time. I.e., it's not a general Redis outage, it's something localized to a specific container.

[hpk]

Any update on this? There seems to be a pretty noticeable increase in connection issues reported for v2.x.

To expand on my previous comment, the primary issue isn't that we see a handful of connection errors/timeouts here and there. It's that we'll often see a single container suddenly just start spewing hundreds of these connection errors. SE.Redis fails to recover and the only resolution is to kill the container.

[Bogatinovski]

We have the same scenario as @hpk. Is there any way to fix this ?

[ispysoftware]

got the same issue here - cache was working fine with 1.2.6, continually falling over with 2+

[unkusr007]

Hello, same kind of issue in 2.0, but also I have this issue only since I'm using elasticache with redis 4.0.
Timeouts are happening if I delete a large number of keys, and I receive a lot a key space notifications.
But in debug on my computer I have no issue using this same database, only in prod (container in ECS).

Timeout performing SREM (30000ms), next: EXISTS cache:thing:stuff:1437bc51-401d-4f35-b0a7-107bd50fdb60:en-US, inst: 1, qu: 0, qs: 91, aw: False, rs: ReadAsync, ws: Idle, in: 848, in-pipe: 0, out-pipe: 0, serverEndpoint: Unspecified/**************:6379, mgr: 10 of 10 available, clientName: 3e5d13637a65, IOCP: (Busy=0,Free=1000,Min=36,Max=1000), WORKER: (Busy=90,Free=32677,Min=36,Max=32767), v: 2.0.601.3402 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)

I tried to add way more vCPU, but the issue is the same.

[satuday]

Hi, I'm experiencing the same issue in a .net core 2.1 project. Any idea on this issue? I'm not see a lot, average around 5 to 10 per day.

Remove cache failed Timeout performing UNLINK organisation-******** (5000ms), inst: 1, qs: 8, in: 352, serverEndpoint: Unspecified/******:6379, mgr: 10 of 10 available, clientName: 580a039d22ca, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=7,Free=32760,Min=2,Max=32767), v: 2.0.513.63329 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts) : at StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImpl[T](Message message, ResultProcessor1 processor, ServerEndPoint server) in C:\\projects\\stackexchange-redis\\src\\StackExchange.Redis\\ConnectionMultiplexer.cs:line 2197 at StackExchange.Redis.RedisBase.ExecuteSync[T](Message message, ResultProcessor1 processor, ServerEndPoint server) in C:\\projects\\stackexchange-redis\\src\\StackExchange.Redis\\RedisBase.cs:line 54 at StackExchange.Redis.RedisDatabase.KeyDelete(RedisKey key, CommandFlags flags) in C:\\projects\\stackexchange-redis\\src\\StackExchange.Redis\\RedisDatabase.cs:line 590

[Alik2015]

We are getting
Connection id "0HLPHO068DD3J", Request id "0HLPHO068DD3J:00000001": An unhandled exception was thrown by the application.
StackExchange.Redis.RedisTimeoutException: Timeout performing EVAL, inst: 7, queue: 9, qu: 0, qs: 9, qc: 0, wr: 0, wq: 0, in: 58988, ar: 0, clientName: , serverEndpoint: Unspecified/*:6379, keyHashSlot: 14678 .

AWS Redis 5
Latest Package for StachExchange from redis.

[RajaInzamam]

Hello All,
StackExchange.Redis.StrongName version : 1.2.1
Microsoft.Web.RedisSessionStateProvider version : 2.2.6.344

All of a sudden our production server (Azure) throwing exception messages:

Exception Category 1 "Timeout performing EVAL, inst: 1, mgr: Inactive, err: never, queue: 17, qu: 0, qs: 17, qc: 0, wr: 0, wq: 0, in: 0, ar: 0, clientName......"

image

Exception Category 2 "No connection is available to service this operation: EVAL; A connection attempt failed because the connected party did not properly respond after a period of time..."

Is this something related to Threadpool Throttling ??

[limoniapps]

Same problem here:

Exception occurred: Timeout performing HGET (5000ms), next: HGET ....com, inst: 3, qu: 0, qs: 2, aw: False, rs: ReadAsync, ws: Idle, in: 0, serverEndpoint: Unspecified/....redis.cache.windows.net:6380, mgr: 10 of 10 available, clientName: RD..., IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=8,Free=8183,Min=1,Max=8191), v: 2.0.601.3402