Exceptions: include Timer.ActiveCount in .NET Core stats

docs/ReleaseNotes.md

@@ -10,6 +10,7 @@ Current package versions:
 
 - Change: Target net6.0 instead of net5.0, since net5.0 is end of life. ([#2497 by eerhardt](https://github.com/StackExchange/StackExchange.Redis/pull/2497))
 - Fix: Fix nullability annotation of IConnectionMultiplexer.RegisterProfiler ([#2494 by eerhardt](https://github.com/StackExchange/StackExchange.Redis/pull/2494))
+- Add: `Timer.ActiveCount` under `POOL` in timeout messages on .NET 6+ to help diagnose timer overload affecting timeout evaluations ([#2500 by NickCraver](https://github.com/StackExchange/StackExchange.Redis/pull/2500))
 
 ## 2.6.116
 

src/StackExchange.Redis/PerfCounterHelper.cs

@@ -23,7 +23,7 @@ internal static int GetThreadPoolStats(out string iocp, out string worker, out s
             worker = $"(Busy={busyWorkerThreads},Free={freeWorkerThreads},Min={minWorkerThreads},Max={maxWorkerThreads})";
 
 #if NETCOREAPP
-            workItems = $"(Threads={ThreadPool.ThreadCount},QueuedItems={ThreadPool.PendingWorkItemCount},CompletedItems={ThreadPool.CompletedWorkItemCount})";
+            workItems = $"(Threads={ThreadPool.ThreadCount},QueuedItems={ThreadPool.PendingWorkItemCount},CompletedItems={ThreadPool.CompletedWorkItemCount},Timers={Timer.ActiveCount})";
 #else
             workItems = null;
 #endif

tests/StackExchange.Redis.Tests/AbortOnConnectFailTests.cs

@@ -16,7 +16,7 @@ public void NeverEverConnectedNoBacklogThrowsConnectionNotAvailableSync()
         var db = conn.GetDatabase();
         var key = Me();
 
-        // No connection is active/available to service this operation: GET 6.0.14AbortOnConnectFailTests-NeverEverConnectedThrowsConnectionNotAvailable; UnableToConnect on doesnot.exist.0d034c26350e4ee199d6c5f385a073f7:6379/Interactive, Initializing/NotStarted, last: NONE, origin: BeginConnectAsync, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 500s, state: Connecting, mgr: 10 of 10 available, last-heartbeat: never, global: 0s ago, v: 2.6.99.22667, mc: 1/1/0, mgr: 10 of 10 available, clientName: NAMISTOU-3(SE.Redis-v2.6.99.22667), IOCP: (Busy=0,Free=1000,Min=32,Max=1000), WORKER: (Busy=2,Free=32765,Min=32,Max=32767), POOL: (Threads=17,QueuedItems=0,CompletedItems=20), v: 2.6.99.22667
+        // No connection is active/available to service this operation: GET 6.0.18AbortOnConnectFailTests-NeverEverConnectedNoBacklogThrowsConnectionNotAvailableSync; UnableToConnect on doesnot.exist.d4d1424806204b68b047954b1db3411d:6379/Interactive, Initializing/NotStarted, last: NONE, origin: BeginConnectAsync, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 100s, state: Connecting, mgr: 4 of 10 available, last-heartbeat: never, global: 0s ago, v: 2.6.120.51136, mc: 1/1/0, mgr: 5 of 10 available, clientName: CRAVERTOP7(SE.Redis-v2.6.120.51136), IOCP: (Busy=0,Free=1000,Min=16,Max=1000), WORKER: (Busy=3,Free=32764,Min=16,Max=32767), POOL: (Threads=25,QueuedItems=0,CompletedItems=1066,Timers=46), v: 2.6.120.51136
         var ex = Assert.Throws<RedisConnectionException>(() => db.StringGet(key));
         Log("Exception: " + ex.Message);
         Assert.Contains("No connection is active/available to service this operation", ex.Message);
@@ -29,7 +29,7 @@ public async Task NeverEverConnectedNoBacklogThrowsConnectionNotAvailableAsync()
         var db = conn.GetDatabase();
         var key = Me();
 
-        // No connection is active/available to service this operation: GET 6.0.14AbortOnConnectFailTests-NeverEverConnectedThrowsConnectionNotAvailable; UnableToConnect on doesnot.exist.0d034c26350e4ee199d6c5f385a073f7:6379/Interactive, Initializing/NotStarted, last: NONE, origin: BeginConnectAsync, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 500s, state: Connecting, mgr: 10 of 10 available, last-heartbeat: never, global: 0s ago, v: 2.6.99.22667, mc: 1/1/0, mgr: 10 of 10 available, clientName: NAMISTOU-3(SE.Redis-v2.6.99.22667), IOCP: (Busy=0,Free=1000,Min=32,Max=1000), WORKER: (Busy=2,Free=32765,Min=32,Max=32767), POOL: (Threads=17,QueuedItems=0,CompletedItems=20), v: 2.6.99.22667
+        // No connection is active/available to service this operation: GET 6.0.18AbortOnConnectFailTests-NeverEverConnectedNoBacklogThrowsConnectionNotAvailableSync; UnableToConnect on doesnot.exist.d4d1424806204b68b047954b1db3411d:6379/Interactive, Initializing/NotStarted, last: NONE, origin: BeginConnectAsync, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 100s, state: Connecting, mgr: 4 of 10 available, last-heartbeat: never, global: 0s ago, v: 2.6.120.51136, mc: 1/1/0, mgr: 5 of 10 available, clientName: CRAVERTOP7(SE.Redis-v2.6.120.51136), IOCP: (Busy=0,Free=1000,Min=16,Max=1000), WORKER: (Busy=3,Free=32764,Min=16,Max=32767), POOL: (Threads=25,QueuedItems=0,CompletedItems=1066,Timers=46), v: 2.6.120.51136
         var ex = await Assert.ThrowsAsync<RedisConnectionException>(() => db.StringGetAsync(key));
         Log("Exception: " + ex.Message);
         Assert.Contains("No connection is active/available to service this operation", ex.Message);
@@ -49,7 +49,7 @@ public void DisconnectAndReconnectThrowsConnectionExceptionSync()
         var server = conn.GetServerSnapshot()[0];
         server.SimulateConnectionFailure(SimulatedFailureType.All);
 
-        // Exception: The message timed out in the backlog attempting to send because no connection became available (100ms) - Last Connection Exception: InternalFailure on 127.0.0.1:6379/Interactive, Initializing/NotStarted, last: GET, origin: ConnectedAsync, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 500s, state: Connecting, mgr: 10 of 10 available, last-heartbeat: never, last-mbeat: 0s ago, global: 0s ago, v: 2.6.99.22667, command=PING, inst: 0, qu: 0, qs: 0, aw: False, bw: CheckingForTimeout, last-in: 0, cur-in: 0, sync-ops: 1, async-ops: 1, serverEndpoint: 127.0.0.1:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: NAMISTOU-3(SE.Redis-v2.6.99.22667), IOCP: (Busy=0,Free=1000,Min=32,Max=1000), WORKER: (Busy=2,Free=32765,Min=32,Max=32767), POOL: (Threads=18,QueuedItems=0,CompletedItems=65), v: 2.6.99.22667 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
+        // Exception: The message timed out in the backlog attempting to send because no connection became available (100ms) - Last Connection Exception: SocketFailure (InputReaderCompleted, last-recv: 7) on 127.0.0.1:6379/Interactive, Idle/ReadAsync, last: PING, origin: SimulateConnectionFailure, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 100s, state: ConnectedEstablished, mgr: 10 of 10 available, in: 0, in-pipe: 0, out-pipe: 0, last-heartbeat: never, last-mbeat: 0s ago, global: 0s ago, v: 2.6.120.51136, command=PING, timeout: 100, inst: 13, qu: 1, qs: 0, aw: False, bw: Inactive, last-in: 0, cur-in: 0, sync-ops: 2, async-ops: 0, serverEndpoint: 127.0.0.1:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: CRAVERTOP7(SE.Redis-v2.6.120.51136), IOCP: (Busy=0,Free=1000,Min=16,Max=1000), WORKER: (Busy=2,Free=32765,Min=16,Max=32767), POOL: (Threads=33,QueuedItems=0,CompletedItems=6237,Timers=39), v: 2.6.120.51136 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
         var ex = Assert.ThrowsAny<Exception>(() => db.Ping());
         Log("Exception: " + ex.Message);
         Assert.True(ex is RedisConnectionException or RedisTimeoutException);
@@ -73,7 +73,7 @@ public async Task DisconnectAndNoReconnectThrowsConnectionExceptionAsync()
         var server = conn.GetServerSnapshot()[0];
         server.SimulateConnectionFailure(SimulatedFailureType.All);
 
-        // Exception: The message timed out in the backlog attempting to send because no connection became available (100ms) - Last Connection Exception: InternalFailure on 127.0.0.1:6379/Interactive, Initializing/NotStarted, last: GET, origin: ConnectedAsync, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 500s, state: Connecting, mgr: 10 of 10 available, last-heartbeat: never, last-mbeat: 0s ago, global: 0s ago, v: 2.6.99.22667, command=PING, inst: 0, qu: 0, qs: 0, aw: False, bw: CheckingForTimeout, last-in: 0, cur-in: 0, sync-ops: 1, async-ops: 1, serverEndpoint: 127.0.0.1:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 10 of 10 available, clientName: NAMISTOU-3(SE.Redis-v2.6.99.22667), IOCP: (Busy=0,Free=1000,Min=32,Max=1000), WORKER: (Busy=2,Free=32765,Min=32,Max=32767), POOL: (Threads=18,QueuedItems=0,CompletedItems=65), v: 2.6.99.22667 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
+        // Exception: The message timed out in the backlog attempting to send because no connection became available (100ms) - Last Connection Exception: SocketFailure (InputReaderCompleted, last-recv: 7) on 127.0.0.1:6379/Interactive, Idle/ReadAsync, last: PING, origin: SimulateConnectionFailure, outstanding: 0, last-read: 0s ago, last-write: 0s ago, keep-alive: 100s, state: ConnectedEstablished, mgr: 8 of 10 available, in: 0, in-pipe: 0, out-pipe: 0, last-heartbeat: never, last-mbeat: 0s ago, global: 0s ago, v: 2.6.120.51136, command=PING, timeout: 100, inst: 0, qu: 0, qs: 0, aw: False, bw: CheckingForTimeout, last-in: 0, cur-in: 0, sync-ops: 1, async-ops: 1, serverEndpoint: 127.0.0.1:6379, conn-sec: n/a, aoc: 0, mc: 1/1/0, mgr: 8 of 10 available, clientName: CRAVERTOP7(SE.Redis-v2.6.120.51136), IOCP: (Busy=0,Free=1000,Min=16,Max=1000), WORKER: (Busy=6,Free=32761,Min=16,Max=32767), POOL: (Threads=33,QueuedItems=0,CompletedItems=5547,Timers=60), v: 2.6.120.51136 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
         var ex = await Assert.ThrowsAsync<RedisConnectionException>(() => db.PingAsync());
         Log("Exception: " + ex.Message);
         Assert.StartsWith("The message timed out in the backlog attempting to send because no connection became available (100ms) - Last Connection Exception: ", ex.Message);

tests/StackExchange.Redis.Tests/ExceptionFactoryTests.cs

@@ -126,7 +126,12 @@ public void TimeoutException()
             Assert.Contains("conn-sec: n/a", ex.Message);
             Assert.Contains("aoc: 1", ex.Message);
 #if NETCOREAPP
-                Assert.Contains("POOL: ", ex.Message);
+            // ...POOL: (Threads=33,QueuedItems=0,CompletedItems=5547,Timers=60)...
+            Assert.Contains("POOL: ", ex.Message);
+            Assert.Contains("Threads=", ex.Message);
+            Assert.Contains("QueuedItems=", ex.Message);
+            Assert.Contains("CompletedItems=", ex.Message);
+            Assert.Contains("Timers=", ex.Message);
 #endif
             Assert.DoesNotContain("Unspecified/", ex.Message);
             Assert.EndsWith(" (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)", ex.Message);