Yes, we still can reproduce the issue in our application without SetMinThreads. When the Redis cache is cleared or expired, if we then request a web page, which triggers a lot of API requests (due loading image thumbnails), then the Redis timeout warnings are logged.
Hi @maliming, I've tried to create a test app, but I couldn't reproduce the same warnings we got from the Redis timeouts. We monitored the thread pool usage:
dotnet-counters monitor --counters System.Runtime -n Fuzed.HttpApi.Host
In the end we ended up updating the min worker threads in our app:
ThreadPool.GetMinThreads(out int minWorkerThreads, out int minCompletionPortThreads);
ThreadPool.SetMinThreads(100, minCompletionPortThreads);
Thanks!
hi @s.beckers
Can you share your test project?
liming.ma@volosoft.com
Thanks.
Hi @maliming, I'll try to create a test project and send it to you.
Is this added to the backlog? Just asking since ServiceBot would like to close this question..
I just found this related question: https://abp.io/support/questions/2880/Redis-performance-issues-in-LanguageManagement-DynamicLocalizationResourceContributor
Please try to remove
DynamicLocalizationResourceContributorand try again.
That does the job! Removing the DynamicLocalizationResourceContributor from the language management module gives a big performance boost. Which functionality do we lose by removing this?
sure, liming.ma@volosoft.com
I've just sent you the full log by email.
@maliming Can I send the full log to you by email?
Thanks for the feedback!
Disabling dynamic claims (which we also don't want to) doesn't fix the issue. I see it's trying to retrieve & expire localizations from the cache?
Stack trace: API log gets spammed with: +- 50 times:
2024-10-02 11:01:19Z [WRN] The message timed out in the backlog attempting to send because no connection became available, command=HMGET, timeout: 5000, outbound: 0KiB, inbound: 1KiB, inst: 0, qu: 37, qs: 0, aw: True, bw: CheckingForTimeoutComplete, rs: ReadAsync, ws: Idle, in: 0, in-pipe: 0, out-pipe: 0, last-in: 1, cur-in: 0, sync-ops: 448, async-ops: 4074, serverEndpoint: localhost:6379, conn-sec: 31,24, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: FZDNOT06(SE.Redis-v2.7.27.49176), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=39,Free=32728,Min=20,Max=32767), POOL: (Threads=39,QueuedItems=47,CompletedItems=68595,Timers=15), 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)
StackExchange.Redis.RedisTimeoutException: The message timed out in the backlog attempting to send because no connection became available, command=HMGET, timeout: 5000, outbound: 0KiB, inbound: 1KiB, inst: 0, qu: 37, qs: 0, aw: True, bw: CheckingForTimeoutComplete, rs: ReadAsync, ws: Idle, in: 0, in-pipe: 0, out-pipe: 0, last-in: 1, cur-in: 0, sync-ops: 448, async-ops: 4074, serverEndpoint: localhost:6379, conn-sec: 31,24, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: FZDNOT06(SE.Redis-v2.7.27.49176), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=39,Free=32728,Min=20,Max=32767), POOL: (Threads=39,QueuedItems=47,CompletedItems=68595,Timers=15), 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)
at StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImpl[T](Message message, ResultProcessor`1 processor, ServerEndPoint server, T defaultValue) in /_/src/StackExchange.Redis/ConnectionMultiplexer.cs:line 2105
at StackExchange.Redis.RedisDatabase.HashGet(RedisKey key, RedisValue[] hashFields, CommandFlags flags) in /_/src/StackExchange.Redis/RedisDatabase.cs:line 407
at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.GetAndRefresh(String key, Boolean getData)
at Volo.Abp.Caching.DistributedCache`2.Get(TCacheKey key, Nullable`1 hideErrors, Boolean considerUow)
2024-10-02 11:01:19Z [WRN] ---------- Exception Data ----------
Redis-Message = HMGET t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:ExternalPortal_en-BE
Redis-Timeout = 5000
Redis-Write-State = Idle
Redis-Read-State = ReadAsync
Redis-OutboundDeltaKB = 0KiB
Redis-InboundDeltaKB = 1KiB
Redis-OpsSinceLastHeartbeat = 0
Redis-Queue-Awaiting-Write = 37
Redis-Queue-Awaiting-Response = 0
Redis-Active-Writer = True
Redis-Backlog-Writer = CheckingForTimeoutComplete
Redis-Inbound-Bytes = 0
Redis-Inbound-Pipe-Bytes = 0
Redis-Outbound-Pipe-Bytes = 0
Redis-Last-Result-Bytes = 1
Redis-Inbound-Buffer-Bytes = 0
Redis-Sync-Ops = 448
Redis-Async-Ops = 4074
Redis-Server-Endpoint = localhost:6379
Redis-Server-Connected-Seconds = 31,24
Redis-Abort-On-Connect = 0
Redis-Multiplexer-Connects = 1/1/0
Redis-Manager = 10 of 10 available
Redis-Client-Name = FZDNOT06(SE.Redis-v2.7.27.49176)
Redis-ThreadPool-IO-Completion = (Busy=0,Free=1000,Min=1,Max=1000)
Redis-ThreadPool-Workers = (Busy=39,Free=32728,Min=20,Max=32767)
Redis-ThreadPool-Items = (Threads=39,QueuedItems=47,CompletedItems=68595,Timers=15)
Redis-Busy-Workers = 39
Redis-Version = 2.7.27.49176
redis-command = HMGET t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:ExternalPortal_en-BE
request-sent-status = WaitingInBacklog
redis-server = localhost:6379
+- 50 times:
2024-10-02 11:01:37Z [WRN] Timeout performing EXPIRE (5000ms), next: EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en, inst: 28, qu: 0, qs: 28, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 1060, in-pipe: 0, out-pipe: 0, last-in: 0, cur-in: 0, sync-ops: 674, async-ops: 4074, serverEndpoint: localhost:6379, conn-sec: 49,66, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: FZDNOT06(SE.Redis-v2.7.27.49176), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=66,Free=32701,Min=20,Max=32767), POOL: (Threads=66,QueuedItems=25,CompletedItems=68718,Timers=14), 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)
StackExchange.Redis.RedisTimeoutException: Timeout performing EXPIRE (5000ms), next: EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en, inst: 28, qu: 0, qs: 28, aw: False, bw: SpinningDown, rs: ReadAsync, ws: Idle, in: 1060, in-pipe: 0, out-pipe: 0, last-in: 0, cur-in: 0, sync-ops: 674, async-ops: 4074, serverEndpoint: localhost:6379, conn-sec: 49,66, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: FZDNOT06(SE.Redis-v2.7.27.49176), IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=66,Free=32701,Min=20,Max=32767), POOL: (Threads=66,QueuedItems=25,CompletedItems=68718,Timers=14), 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)
at StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImpl[T](Message message, ResultProcessor`1 processor, ServerEndPoint server, T defaultValue) in /_/src/StackExchange.Redis/ConnectionMultiplexer.cs:line 2105
at StackExchange.Redis.RedisDatabase.KeyExpire(RedisKey key, Nullable`1 expiry, ExpireWhen when, CommandFlags flags) in /_/src/StackExchange.Redis/RedisDatabase.cs:line 840
at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.Refresh(IDatabase cache, String key, Nullable`1 absExpr, Nullable`1 sldExpr)
at Microsoft.Extensions.Caching.StackExchangeRedis.RedisCache.GetAndRefresh(String key, Boolean getData)
at Volo.Abp.Caching.DistributedCache`2.Get(TCacheKey key, Nullable`1 hideErrors, Boolean considerUow)
2024-10-02 11:01:37Z [WRN] ---------- Exception Data ----------
Redis-Message = EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en-BE
Redis-Message-Next = EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en
Redis-OpsSinceLastHeartbeat = 28
Redis-Queue-Awaiting-Write = 0
Redis-Queue-Awaiting-Response = 28
Redis-Active-Writer = False
Redis-Backlog-Writer = SpinningDown
Redis-Read-State = ReadAsync
Redis-Write-State = Idle
Redis-Inbound-Bytes = 1060
Redis-Inbound-Pipe-Bytes = 0
Redis-Outbound-Pipe-Bytes = 0
Redis-Last-Result-Bytes = 0
Redis-Inbound-Buffer-Bytes = 0
Redis-Sync-Ops = 674
Redis-Async-Ops = 4074
Redis-Server-Endpoint = localhost:6379
Redis-Server-Connected-Seconds = 49,66
Redis-Abort-On-Connect = 0
Redis-Multiplexer-Connects = 1/1/0
Redis-Manager = 10 of 10 available
Redis-Client-Name = FZDNOT06(SE.Redis-v2.7.27.49176)
Redis-ThreadPool-IO-Completion = (Busy=0,Free=1000,Min=1,Max=1000)
Redis-ThreadPool-Workers = (Busy=66,Free=32701,Min=20,Max=32767)
Redis-ThreadPool-Items = (Threads=66,QueuedItems=25,CompletedItems=68718,Timers=14)
Redis-Busy-Workers = 66
Redis-Version = 2.7.27.49176
redis-command = EXPIRE t:661be86b-0b72-db1a-9151-3a0624e8440d,c:Volo.Abp.LanguageManagement.Texts,k:Fuzed:Platform_en-BE
request-sent-status = Sent
redis-server = localhost:6379
+- 50 times:
2024-10-02 11:01:41Z [DBG] Added 0 entity changes to the current audit log
Thanks! Increasing the MinThreads seems to work:
public class Program
{
public static async Task<int> Main(string[] args)
{
try
{
...
System.Threading.ThreadPool.GetMinThreads(out int minWorkerThreads, out int minCompletionPortThreads);
System.Threading.ThreadPool.SetMinThreads(minWorkerThreads * 50, minCompletionPortThreads * 50);
...
}
...
}
}
I've tested this by multiplying the MinThreads with 50, resulting in 1000 worker threads and 50 completion port threads. I'm not sure if this is a best practice. Is 50 times too much? How should I choose a good amount of threads?
This might also result in some other issues according to Microsoft docs: https://learn.microsoft.com/en-us/dotnet/standard/threading/the-managed-thread-pool#thread-pool-minimums
Isn't this just a framework issue? Calling the cache too much? I would think that the managed thread pool should do it's job just fine, without adjusting the minimum of worker threads.
