Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Runtime net8.0+ StackExchange.Redis.RedisTimeoutException error rate grows rapidly after upgrading target framework from .net 6 to 8.0 #102312

Open
haihao-gd opened this issue May 16, 2024 · 4 comments
Open

Runtime net8.0+ StackExchange.Redis.RedisTimeoutException error rate grows rapidly after upgrading target framework from .net 6 to 8.0 #102312

haihao-gd opened this issue May 16, 2024 · 4 comments
Labels
area-System.Threading tenet-performance Performance related issue untriaged New issue has not been triaged by the area owner

Comments

@haihao-gd
Copy link

haihao-gd commented May 16, 2024 •
edited

Description

StackExchange.Redis.RedisTimeoutException error rate grows rapidly after upgrading StackExchange.Redis from .net 6 to 8.0

exception: StackExchange.Redis.RedisTimeoutException: Timeout performing GET (1000ms), next: GET Key_xxxx, inst: 4, qu: 0, qs: 0, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 4376, last-in: 2828, cur-in: 0, sync-ops: 3428, async-ops: 0, serverEndpoint: xxxxxx.azure.net:10000, conn-sec: 7941.28, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: , IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=11,Free=32756,Min=2,Max=32767), POOL: (Threads=24,QueuedItems=23,CompletedItems=175543,Timers=55), v: 2.7.33.41805 (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, T defaultValue) in /_/src/StackExchange.Redis/ConnectionMultiplexer.cs:line 2111 at StackExchange.Redis.RedisBase.ExecuteSync[T](Message message, ResultProcessor1 processor, ServerEndPoint server, T defaultValue) in //src/StackExchange.Redis/RedisBase.cs:line 62
at StackExchange.Redis.RedisDatabase.StringGet(RedisKey key, CommandFlags flags) in //src/StackExchange.Redis/RedisDatabase.cs:line 2994
at XCompany.Caching.LazyCache.Get[T](String key) Redis-Message: GET Key_430B5850-CB76-4634-8E0E-D8FA8482C59A;Redis-Message-Next: GET Key_xxxx;Redis-OpsSinceLastHeartbeat: 4;Redis-Queue-Awaiting-Write: 0;Redis-Queue-Awaiting-Response: 0;Redis-Active-Writer: False;Redis-Backlog-Writer: SpinningDown;Redis-Read-State: ReadAsync;Redis-Write-State: Idle;Redis-Inbound-Bytes: 4376;Redis-Last-Result-Bytes: 2828;Redis-Inbound-Buffer-Bytes: 0;Redis-Sync-Ops: 3428;Redis-Async-Ops: 0;Redis-Server-Endpoint: xxxxxx.azure.net:10000;Redis-Server-Connected-Seconds: 7941.28;Redis-Abort-On-Connect: 0;Redis-Multiplexer-Connects: 1/1/0;Redis-Manager: 10 of 10 available;Redis-Client-Name: ;Redis-ThreadPool-IO-Completion: (Busy=0,Free=1000,Min=2,Max=1000);Redis-ThreadPool-Workers: (Busy=11,Free=32756,Min=2,Max=32767);Redis-ThreadPool-Items: (Threads=24,QueuedItems=23,CompletedItems=175543,Timers=55);Redis-Busy-Workers: 11;Redis-Version: 2.7.33.41805;redis-command: GET Key_430B5850-CB76-4634-8E0E-D8FA8482C59A;request-sent-status: Sent;redis-server: xxxxxx.azure.net:10000

Configuration

image

  • Which version of .NET is the code running on?
    Host:
    Version: 8.0.2
    Architecture: x64
    Commit: 1381d5e
    RID: win-x64

  • What OS version, and what distro if applicable?
    image

  • What is the architecture (x64, x86, ARM, ARM64)?
    X64

  • If relevant, what are the specs of the machine?

Regression?

Performance testing

Data

image

exception: StackExchange.Redis.RedisTimeoutException: Timeout performing GET (1000ms), next: GET Key_xxxx, inst: 4, qu: 0, qs: 0, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 4376, last-in: 2828, cur-in: 0, sync-ops: 3428, async-ops: 0, serverEndpoint: xxxxxx.azure.net:10000, conn-sec: 7941.28, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: , IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=11,Free=32756,Min=2,Max=32767), POOL: (Threads=24,QueuedItems=23,CompletedItems=175543,Timers=55), v: 2.7.33.41805 (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, T defaultValue) in /_/src/StackExchange.Redis/ConnectionMultiplexer.cs:line 2111 at StackExchange.Redis.RedisBase.ExecuteSync[T](Message message, ResultProcessor1 processor, ServerEndPoint server, T defaultValue) in //src/StackExchange.Redis/RedisBase.cs:line 62
at StackExchange.Redis.RedisDatabase.StringGet(RedisKey key, CommandFlags flags) in //src/StackExchange.Redis/RedisDatabase.cs:line 2994
at XCompany.Caching.LazyCache.Get[T](String key) Redis-Message: GET Key_430B5850-CB76-4634-8E0E-D8FA8482C59A;Redis-Message-Next: GET Key_xxxx;Redis-OpsSinceLastHeartbeat: 4;Redis-Queue-Awaiting-Write: 0;Redis-Queue-Awaiting-Response: 0;Redis-Active-Writer: False;Redis-Backlog-Writer: SpinningDown;Redis-Read-State: ReadAsync;Redis-Write-State: Idle;Redis-Inbound-Bytes: 4376;Redis-Last-Result-Bytes: 2828;Redis-Inbound-Buffer-Bytes: 0;Redis-Sync-Ops: 3428;Redis-Async-Ops: 0;Redis-Server-Endpoint: xxxxxx.azure.net:10000;Redis-Server-Connected-Seconds: 7941.28;Redis-Abort-On-Connect: 0;Redis-Multiplexer-Connects: 1/1/0;Redis-Manager: 10 of 10 available;Redis-Client-Name: ;Redis-ThreadPool-IO-Completion: (Busy=0,Free=1000,Min=2,Max=1000);Redis-ThreadPool-Workers: (Busy=11,Free=32756,Min=2,Max=32767);Redis-ThreadPool-Items: (Threads=24,QueuedItems=23,CompletedItems=175543,Timers=55);Redis-Busy-Workers: 11;Redis-Version: 2.7.33.41805;redis-command: GET Key_430B5850-CB76-4634-8E0E-D8FA8482C59A;request-sent-status: Sent;redis-server: xxxxxx.azure.net:10000

BenchmarkDotNet v0.13.12, Windows 11 (10.0.22631.3447/23H2/2023Update/SunValley3)

11th Gen Intel Core i7-1165G7 2.80GHz, 1 CPU, 8 logical and 4 physical cores

.NET SDK 8.0.204

[Host] : .NET 8.0.4 (8.0.424.16909), X64 RyuJIT AVX-512F+CD+BW+DQ+VL+VBMI [AttachedDebugger]

DefaultJob : .NET 8.0.4 (8.0.424.16909), X64 RyuJIT AVX-512F+CD+BW+DQ+VL+VBMI

| Method | Mean | Error | StdDev | Median |

|------------- |---------:|--------:|--------:|---------:|

| GetCacheItem | 205.7 ms | 3.77 ms | 6.40 ms | 202.6 ms |

| SetCacheItem | 203.1 ms | 3.72 ms | 3.30 ms | 201.8 ms |

BenchmarkDotNet v0.13.12, Windows 11 (10.0.22631.3447/23H2/2023Update/SunValley3)

11th Gen Intel Core i7-1165G7 2.80GHz, 1 CPU, 8 logical and 4 physical cores

.NET SDK 8.0.204

[Host] : .NET 6.0.28 (6.0.2824.12007), X64 RyuJIT AVX2 [AttachedDebugger]

DefaultJob : .NET 6.0.28 (6.0.2824.12007), X64 RyuJIT AVX2

| Method | Mean | Error | StdDev |

|------------- |---------:|--------:|--------:|

| GetCacheItem | 202.4 ms | 0.86 ms | 0.72 ms |

| SetCacheItem | 202.2 ms | 1.70 ms | 1.32 ms |

Analysis

Possibly dependent on changes to the thread pool and changes to asynchrony and synchronization in the new version of runtime
@haihao-gd haihao-gd added the tenet-performance Performance related issue label May 16, 2024
@dotnet-policy-service dotnet-policy-service bot added the untriaged New issue has not been triaged by the area owner label May 16, 2024
@dotnet-policy-service Dotnet Policy Service
Copy link
Contributor

Tagging subscribers to this area: @mangod9
See info in area-owners.md if you want to be subscribed.

@haihao-gd
Copy link
Author

.net 6
// * Detailed results *
LazyCacheBenchmark.GetCacheItem: DefaultJob
Runtime = .NET 6.0.28 (6.0.2824.12007), X64 RyuJIT AVX2; GC = Concurrent Workstation
Mean = 202.362 ms, StdErr = 0.199 ms (0.10%), N = 13, StdDev = 0.717 ms
Min = 201.180 ms, Q1 = 201.936 ms, Median = 202.374 ms, Q3 = 202.723 ms, Max = 203.831 ms
IQR = 0.787 ms, LowerFence = 200.756 ms, UpperFence = 203.904 ms
ConfidenceInterval = [201.504 ms; 203.221 ms] (CI 99.9%), Margin = 0.859 ms (0.42% of Mean)
Skewness = 0.3, Kurtosis = 2.26, MValue = 2
-------------------- Histogram --------------------
[200.780 ms ; 204.231 ms) | @@@@@@@@@@@@@

LazyCacheBenchmark.SetCacheItem: DefaultJob
Runtime = .NET 6.0.28 (6.0.2824.12007), X64 RyuJIT AVX2; GC = Concurrent Workstation
Mean = 202.191 ms, StdErr = 0.382 ms (0.19%), N = 12, StdDev = 1.324 ms
Min = 201.097 ms, Q1 = 201.378 ms, Median = 201.799 ms, Q3 = 202.488 ms, Max = 205.875 ms
IQR = 1.110 ms, LowerFence = 199.712 ms, UpperFence = 204.154 ms
ConfidenceInterval = [200.494 ms; 203.887 ms] (CI 99.9%), Margin = 1.696 ms (0.84% of Mean)
Skewness = 1.67, Kurtosis = 5.13, MValue = 2
-------------------- Histogram --------------------
[200.338 ms ; 206.634 ms) | @@@@@@@@@@@@

// * Summary *

BenchmarkDotNet v0.13.12, Windows 11 (10.0.22631.3447/23H2/2023Update/SunValley3)
11th Gen Intel Core i7-1165G7 2.80GHz, 1 CPU, 8 logical and 4 physical cores
.NET SDK 8.0.204
[Host] : .NET 6.0.28 (6.0.2824.12007), X64 RyuJIT AVX2 [AttachedDebugger]
DefaultJob : .NET 6.0.28 (6.0.2824.12007), X64 RyuJIT AVX2

Method Mean Error StdDev
GetCacheItem 202.4 ms 0.86 ms 0.72 ms
SetCacheItem 202.2 ms 1.70 ms 1.32 ms

// * Warnings *
Environment
Summary -> Benchmark was executed with attached debugger

// * Hints *
Outliers
LazyCacheBenchmark.GetCacheItem: Default -> 2 outliers were removed (206.08 ms, 348.33 ms)
LazyCacheBenchmark.SetCacheItem: Default -> 3 outliers were removed (218.02 ms..347.24 ms)

.net 8
// * Detailed results *
LazyCacheBenchmark.GetCacheItem: DefaultJob
Runtime = .NET 8.0.4 (8.0.424.16909), X64 RyuJIT AVX-512F+CD+BW+DQ+VL+VBMI; GC = Concurrent Workstation
Mean = 203.614 ms, StdErr = 0.594 ms (0.29%), N = 40, StdDev = 3.760 ms
Min = 201.131 ms, Q1 = 201.760 ms, Median = 202.251 ms, Q3 = 203.110 ms, Max = 219.911 ms
IQR = 1.350 ms, LowerFence = 199.736 ms, UpperFence = 205.135 ms
ConfidenceInterval = [201.499 ms; 205.730 ms] (CI 99.9%), Margin = 2.115 ms (1.04% of Mean)
Skewness = 2.68, Kurtosis = 10.39, MValue = 2
-------------------- Histogram --------------------
[200.474 ms ; 207.256 ms) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[207.256 ms ; 215.134 ms) | @@@@
[215.134 ms ; 221.354 ms) | @

LazyCacheBenchmark.SetCacheItem: DefaultJob
Runtime = .NET 8.0.4 (8.0.424.16909), X64 RyuJIT AVX-512F+CD+BW+DQ+VL+VBMI; GC = Concurrent Workstation
Mean = 200.986 ms, StdErr = 0.598 ms (0.30%), N = 13, StdDev = 2.158 ms
Min = 199.048 ms, Q1 = 199.399 ms, Median = 199.926 ms, Q3 = 201.912 ms, Max = 205.963 ms
IQR = 2.513 ms, LowerFence = 195.628 ms, UpperFence = 205.682 ms
ConfidenceInterval = [198.402 ms; 203.570 ms] (CI 99.9%), Margin = 2.584 ms (1.29% of Mean)
Skewness = 0.97, Kurtosis = 2.68, MValue = 2
-------------------- Histogram --------------------
[198.246 ms ; 207.167 ms) | @@@@@@@@@@@@@

// * Summary *

BenchmarkDotNet v0.13.12, Windows 11 (10.0.22631.3447/23H2/2023Update/SunValley3)
11th Gen Intel Core i7-1165G7 2.80GHz, 1 CPU, 8 logical and 4 physical cores
.NET SDK 8.0.204
[Host] : .NET 8.0.4 (8.0.424.16909), X64 RyuJIT AVX-512F+CD+BW+DQ+VL+VBMI [AttachedDebugger]
DefaultJob : .NET 8.0.4 (8.0.424.16909), X64 RyuJIT AVX-512F+CD+BW+DQ+VL+VBMI

Method Mean Error StdDev
GetCacheItem 203.6 ms 2.12 ms 3.76 ms
SetCacheItem 201.0 ms 2.58 ms 2.16 ms

// * Warnings *
Environment
Summary -> Benchmark was executed with attached debugger

// * Hints *
Outliers
LazyCacheBenchmark.GetCacheItem: Default -> 13 outliers were removed (283.28 ms..461.56 ms)
LazyCacheBenchmark.SetCacheItem: Default -> 2 outliers were removed (273.34 ms, 390.34 ms)

@mangod9
Copy link
Member

mangod9 commented May 16, 2024

Hello @haihao-gd, perhaps you should create the issue against https://github.com/StackExchange/StackExchange.Redis? They can do an initial assessment of the issue? Thanks

@haihao-gd
Copy link
Author

Hello @haihao-gd, perhaps you should create the issue against https://github.com/StackExchange/StackExchange.Redis? They can do an initial assessment of the issue? Thanks

team just upgraded the target framework without changing the Redis related logic, and there is a ticket #9308 related to this type in the issue history to refer to whether the problem has reappeared

@haihao-gd haihao-gd changed the title Runtime net8.0+ StackExchange.Redis.RedisTimeoutException error rate grows rapidly after upgrading StackExchange.Redis from .net 6 to 8.0 Runtime net8.0+ StackExchange.Redis.RedisTimeoutException error rate grows rapidly after upgrading target framework from .net 6 to 8.0 May 17, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area-System.Threading tenet-performance Performance related issue untriaged New issue has not been triaged by the area owner
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@mangod9 @haihao-gd