Timeouts observed with StackExchange.Redis under load

[SachinRamRN]

We are experiencing frequent Timeout awaiting response errors while using StackExchange.Redis (v2.10.1) against an Azure Redis Cache C0 instance
Currently, the Redis cache stores minimal data, but under moderate load (~hundreds of requests/sec), we see a large number of timeouts.

Timeout awaiting response (outbound=0KiB, inbound=0KiB, 6500ms elapsed, timeout is 5000ms), command=GET, next: SET 2700758, inst: 0, qu: 0, qs: 0, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 371, last-in: 2, cur-in: 0, sync-ops: 1, async-ops: 363, serverEndpoint: 20.198.145.151:8501, conn-sec: 80376.19, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: f1fd87ec2fb3(SE.Redis-v2.10.1.65101), PerfCounterHelperkeyHashSlot: 6029, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=20,Free=32747,Min=2,Max=32767), POOL: (Threads=20,QueuedItems=69,CompletedItems=1218359,Timers=36), v: 2.10.1.65101 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)

The CPU usage on both the application and Redis server is minimal, around 30–50%, so this does not appear to be CPU-bound.
We are using a single ConnectionMultiplexer across the application.

string redisConnectionString = Configuration.GetSection("Redis").GetSection("ConnectionString").Value; var redisConnection = ConnectionMultiplexer.Connect(redisConnectionString);

The logs show many in-flight commands, which makes us wonder whether these timeouts indicate that the messages have reached the client kernel, or if they are queued somewhere in the client library or network stack. We would like to understand what “in:342” generally means does it indicate requests that have been sent to Redis but not yet acknowledged, or does it include requests still queued inside the client library?

We also notice the POOL thread count in the logs is 20, and we would like to understand how these internal threads are allocated, whether they are dedicated or shared from the global thread pool, and how they affect request processing.

We are trying to determine whether these timeouts are caused by network-bound limitations on the C0 tier, client-side saturation due to a single multiplexer and many in-flight commands, or inherent throughput limits of the C0 instance.

[mgravell]

in here is the number of bytes available and waiting to be read from the socket. You say there are "many in-flight commands", but I'm not sure this shows that - qu and qs are the unsent and sent queue lengths, respectively - both are zero; although I guess that might be misleadingly reporting zero if the library has already decided to burn this connection and flushed them. sync-ops and async-ops are purely incremental, and help us understand the mix of sync and async from a "thread starvation" angle - you're looking fully async, so: no problem there. mc is the connect-attempt/connect-complete-connection-close counts, so: that looks OK - tried once, connected once, failed zero.

363 is almost literally nothing (I can push 2M+ ops/s through a local server from a single connection), so by itself I see nothing causal here. But: I also note that this connection has been alive for 22 hours. The "Threads/QueuedItems/CompletedItems" numbers are for the overall managed thread-pool, and are not specific to SE.Redis, so: there's not necessarily anything useful in those numbers.

So it looks like this is a fairly idle connection that has been open for nearly a day, doing not much, that is sticky at some point later. I wonder if enabling HeartbeatConsistencyChecks (config-options) might be applicable. But I'm a little confused, because the default heartbeat should already be being used, which means I would have expected lots more traffic... maybe heartbeats aren't touching the ops counters? I'll check. Can you tell me whether this aligns with what you expect this connection to be doing? You say "~hundreds of requests/sec"... I don't see that here, unless I've borked the op counters (which is possible, I'm fallible), or unless you're actually spinning up multiple connections. This question actually tempts to track the overall muxer counts (created+collected+delta), for our understanding.

Note that throughput and blockages can be hugely dependent on the size of payloads; sending 1 gig takes time, in any setup. Is it possible that we're actually bandwidth constrained by large payloads? Also, load at the server can often be "spikey", meaning: average CPU tells you nothing, if the server was busy at just the wrong time. The SLOWLOG command might be helpful there.

I don't know what server version you're using, but if it is bleeding edge, the HOTKEYS command can also be useful for investigating server-side utilization.

v2.1.10 is suitably recent that I'm not confused by "what has/hasn't changed since then" - although by the same token: it should be pain-free to update to latest (or wait a few days and update to the version with the muxer-count) just to simplify things.

[mgravell]

There's a build on our myget feed that tracks the muxer count; it don't expect it to magically fix anything, but: might be useful for diagnostic purposes; feed url: https://www.myget.org/F/stackoverflow/api/v3/index.json

I don't think it warrants a NuGet deploy by itself.

[SachinRamRN]

@mgravell Thanks for the comment!

var options = ConfigurationOptions.Parse(redisConnectionString);
options.AbortOnConnectFail = false;
options.ConnectRetry = 5;
options.KeepAlive = 180;
options.ReconnectRetryPolicy = new ExponentialRetry(5000);
options.HeartbeatConsistencyChecks = true; 

var redisConnection = ConnectionMultiplexer.Connect(options);
services.AddSingleton<IConnectionMultiplexer>(redisConnection);

I’ve used a single ConnectionMultiplexer, so there’s no chance of multiple connections being created.
Thanks for the detailed breakdown. I’ll try enabling HeartbeatConsistencyChecks and see how it affects connection behavior. I’ll investigate the results and follow up with any observations.

Do you think this configuration needs any further changes, or is it fine as-is?

[mgravell]

The setup looks fine to me. Was there anything inconsistent in my "what I see from the message" overview? In particular, I'm intrigued about the counts: you said this is under hundreds of requests a second, but that counts are low. I guess they could have wrapped around, but that would take 47k+ ops/s to do in that time interval. So if you're confident about the throughout rate, it probably means I've missed a counter increment somewhere! I'm also tempted to add an ops/s tracker (instantaneous or expoential decay, whatever), maybe measured between heartbeats.