StackExchange / StackExchange.Redis

General purpose redis client
https://stackexchange.github.io/StackExchange.Redis/
Other
5.91k stars 1.51k forks source link

Timeout performing EVAL (5000ms) error during local debugging with Azure Cache for Redis resource #2663

Open enginaydogdu opened 8 months ago

enginaydogdu commented 8 months ago

Hi,

We use Azure Cache for Redis version 6.0 for our .net 4.7.2 application and during debugging the application locally we get the error below. We use the same Redis resource for our test environment and it works properly there but during locally we get error. Sometimes it happens more frequently sometimes rarely.

Does anybody have an idea why does it occur? Thanks in advance.

Timeout performing EVAL (5000ms), 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: 200, async-ops: 1, serverEndpoint: {serverEndpoint}, conn-sec: 387,79, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: {clientName} (SE.Redis-v2.7.27.49176)(Microsoft.Web.RedisSessionStateProvider-v5.1.0.0), IOCP: (Busy=0,Free=1000,Min=12,Max=1000), WORKER: (Busy=3,Free=32764,Min=12,Max=32767), v: 2.7.27.49176 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)

mgravell commented 8 months ago

as with any timeout, it occurred because we didn't get (or process) a prompt response; I can't tell you exactly why we didn't get a prompt response; it could have been a server stall, it could have been a network stall, it could have been a broken socket, it could have been a bunch of things - have you checked SLOWLOG etc on the server to see if it was a server-side stall?

philon-msft commented 8 months ago

Network latency between the Redis cache and your local dev machine will also be much higher than when your Redis client code is running in your test environment (presumably in the same Azure data center as your Redis cache). That longer transmission time when debugging locally will vary, and could cause commands to timeout.

enginaydogdu commented 8 months ago

as with any timeout, it occurred because we didn't get (or process) a prompt response; I can't tell you exactly why we didn't get a prompt response; it could have been a server stall, it could have been a network stall, it could have been a broken socket, it could have been a bunch of things - have you checked SLOWLOG etc on the server to see if it was a server-side stall?

Yes, you may see logs below. Do you see a valuable information in it?

1) 1) (integer) 240 2) (integer) 1709893928 3) (integer) 30145 4) 1) "setclientaddr" 2) "52.174.142.160:1025" 3) "yes" 5) "52.174.142.160:1025" 6) "" 2) 1) (integer) 239 2) (integer) 1709893010 3) (integer) 107662 4) 1) "setclientaddr" 2) "52.174.142.160:1034" 3) "yes" 5) "52.174.142.160:1034" 6) "" 3) 1) (integer) 238 2) (integer) 1709812270 3) (integer) 10618 4) 1) "setclientaddr" 2) "52.174.142.160:2058" 3) "yes" 5) "52.174.142.160:2058" 6) "" 4) 1) (integer) 237 2) (integer) 1709810531 3) (integer) 20913 4) 1) "EVALSHA" 2) "71fe2e7962348b06aa8ce3e244cdb3f774b4f549" 3) "3" 4) "{/_v3hwbs4cemtjb4coh50ehnyd}_Write_Lock" 5) "{/_v3hwbs4cemtjb4coh50ehnyd}_Data" 6) "{/_v3hwbs4cemtjb4coh50ehnyd}_Internal" 7) "638454073317090188" 8) "110" 5) "13.94.249.73:30957" 6) "pd0sdwk000CSU" 5) 1) (integer) 236 2) (integer) 1709807815 3) (integer) 38821 4) 1) "INFO" 2) "replication" 5) "13.94.249.73:30957" 6) "pd0sdwk000CSU" 6) 1) (integer) 235 2) (integer) 1709806867 3) (integer) 10653 4) 1) "setclientaddr" 2) "52.174.142.160:2048" 3) "yes" 5) "52.174.142.160:2048" 6) "" 7) 1) (integer) 234 2) (integer) 1709806408 3) (integer) 29430 4) 1) "setclientaddr" 2) "172.16.0.4:51393" 3) "yes" 5) "172.16.0.4:51393" 6) "" 8) 1) (integer) 233 2) (integer) 1709804659 3) (integer) 95958 4) 1) "setclientaddr" 2) "172.16.0.4:23982" 3) "yes" 5) "172.16.0.4:23982" 6) "" 9) 1) (integer) 232 2) (integer) 1709800135 3) (integer) 15887 4) 1) "setclientaddr" 2) "172.16.0.4:52094" 3) "yes" 5) "172.16.0.4:52094" 6) "" 10) 1) (integer) 231 2) (integer) 1709798024 3) (integer) 49976 4) 1) "setclientaddr" 2) "172.16.0.4:18954" 3) "yes" 5) "172.16.0.4:18954" 6) ""

enginaydogdu commented 8 months ago

Network latency between the Redis cache and your local dev machine will also be much higher than when your Redis client code is running in your test environment (presumably in the same Azure data center as your Redis cache). That longer transmission time when debugging locally will vary, and could cause commands to timeout.

Makes sense. Do you know is there a way to increase timeout for eval? I tried to increase all the timeouts I saw in ConfigurationOptions but still getting error below that says Timeout performing EVAL (5000ms)

Timeout performing EVAL (5000ms), next: EVAL, inst: 0, qu: 0, qs: 0, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 22195, last-in: 0, cur-in: 4, sync-ops: 271, async-ops: 1,

var options = new ConfigurationOptions { EndPoints = { connectionString }, Password = password, AbortOnConnectFail = false, AsyncTimeout = 20_000, SyncTimeout = 20_000, ConnectTimeout = 20_000, ConnectRetry = 10, Ssl = true, SslProtocols = SslProtocols.Tls12, IncludeDetailInExceptions = true, };

philon-msft commented 8 months ago

Setting SyncTimeout and AsyncTimeout to 20000 should be sufficient to increase the timeout for all commands including EVAL. If you're still seeing timeouts at 5000ms, those options may not be getting applied correctly. Are you using ScriptEvaluate() or ScriptEvaluateAsync() to execute the EVAL command?