StackExchange / StackExchange/StackExchange.Redis

Persistent timeouts all of a sudden

Open
#2,567 6 comments 1 reaction 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
C#
Stars
6.2k
Forks
1.6k
Avg merge
1d 15h
Merged PRs (30d)
43

Description

I've been using Redis for several years via the RedisSessionStateProvider from an Azure web app.

From time to time, I've encountered a situation where the session state provider would start failing with errors due to timeouts while executing Redis operations. Until now, I've been able to resolve these by restarting the web app which, I suppose, clears the queue of Redis requests. Last February, I posted an issue about that where I was given a suggestion to upgrade the relevant NuGet packages, which I've done, and haven't encountered an issue until today.

Currently installed packages:

  • Microsoft.Redis.SessionStateProvider - 4.0.1
  • StackExchange.Redis - 2.6.90

Today, I encountered an issue where the app was experiencing a flurry of Redis timeouts. This time, restarting the web app did not resolve the issue, but rather, the timeouts came back almost immediately. I also tried failing over my web app to another, usually dormant, web app instance in a different Azure region, and the timeouts immediately started showing up in that instance. I also tried using the Reboot panel on the Redis cache in the Azure Portal, but to no avail.

Here are some examples of the errors I was receiving:

Timeout performing EVAL (1000ms), next: EVAL, inst: 0, qu: 0, qs: 0, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 0, last-in: 0, cur-in: 0, sync-ops: 24839, async-ops: 1, serverEndpoint: *****.redis.cache.windows.net:6380, conn-sec: 3632.63, mc: 1/1/0, mgr: 10 of 10 available, clientName: dw0sdwk0001C6(SE.Redis-v2.6.90.64945), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=9,Free=8182,Min=1,Max=8191), v: 2.6.90.64945

Timeout performing EVAL (1000ms), next: EVAL, inst: 0, qu: 0, qs: 0, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 1082, last-in: 0, cur-in: 0, sync-ops: 24839, async-ops: 1, serverEndpoint: *****.redis.cache.windows.net:6380, conn-sec: 3632.7, mc: 1/1/0, mgr: 10 of 10 available, clientName: dw0sdwk0001C6(SE.Redis-v2.6.90.64945), IOCP: (Busy=1,Free=999,Min=1,Max=1000), WORKER: (Busy=8,Free=8183,Min=1,Max=8191), v: 2.6.90.64945

Timeout performing EVAL (1000ms), next: EVAL, inst: 0, qu: 0, qs: 0, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 1082, last-in: 0, cur-in: 0, sync-ops: 24839, async-ops: 1, serverEndpoint: *****.redis.cache.windows.net:6380, conn-sec: 3632.71, mc: 1/1/0, mgr: 10 of 10 available, clientName: dw0sdwk0001C6(SE.Redis-v2.6.90.64945), IOCP: (Busy=1,Free=999,Min=1,Max=1000), WORKER: (Busy=7,Free=8184,Min=1,Max=8191), v: 2.6.90.64945

Until now, I have been using a C0 size Redis cache, but today, I had the thought that it being shared infrastructure might be the cause of the issue, and scaled up to C1. At the same, I scaled out my web app from 2 instances to 4 in case the bottleneck was within the app.

After performing these two actions, the timeout errors drastically decreased, but did not go away entirely, occurring a few times every few minutes. Naturally, I'm not sure which of these two changes actually had the effect, or whether it was a combination of both.

Monitoring in Azure shows the traffic to my web app to be consistent with other weekdays from the past month, but I'm wondering if this could be simply a matter of the app accessing session state at a pace where the requests to the Redis cache can't keep up?

I would greatly appreciate any advice as to how to troubleshoot or improve this issue.

Current settings:

        <add name="RedisCacheStore" type="Microsoft.Web.Redis.RedisSessionStateProvider"
             host="#{RedisHost}#"
             port="6380"
             accessKey="#{RedisKey}#"
             ssl="True"
             connectionTimeoutInMilliseconds="15000" 
             operationTimeoutInMilliseconds="1000"
             retryTimeoutInMilliseconds="3000"
        />

Some findings from the metrics in Azure:

It looks like cache's server load has been steadily increasing since Sept. 13, before shooting up to 100% yesterday. Before that, there were spikes followed by a return to baseline:

image

Cache latency shows a similar trend:

image

By comparison, traffic to my web app has followed a consistent pattern for the past month, with peaks during US business times on weekdays, and the usual amount of traffic today:

image

The cache's Total Operations and Cache Hits follow a similar trend to the web app, though they seem to have doubled today:

image

image

Max CPU and Connections Created, which have been fairly flat all month, suddenly shot way up today.

image

image

Are there any insights I can draw from these stats as to what the root cause could be?

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with the supplied EVAL timeout traces, RedisSessionStateProvider XML settings, and Azure cache metrics. Compare server load, latency, operations, CPU, connections, and web-app traffic around the incident; done means identifying a supported root cause and a concrete remediation for the recurring timeouts.

Written by the indexing model from the issue text.

Assessment

Tech stack
csharp, redis
Domain
databases
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.