CSHARP-5046: Test that durations are included on relevant pool events (#1526)

sanych-sun · web-flow · commit b0f02ee524b7 · 2024-11-18T14:15:08.000-08:00
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkin-make-available.json b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkin-make-available.json
@@ -22,7 +22,8 @@
     {
       "type": "ConnectionCheckedOut",
       "connectionId": 1,
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckedIn",
@@ -32,7 +33,8 @@
     {
       "type": "ConnectionCheckedOut",
       "connectionId": 1,
-      "address": 42
+      "address": 42,
+      "duration": 42
     }
   ],
   "ignore": [
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkin-make-available.yml b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkin-make-available.yml
@@ -12,12 +12,14 @@ events:
   - type: ConnectionCheckedOut
     connectionId: 1
     address: 42
+    duration: 42
   - type: ConnectionCheckedIn
     connectionId: 1
     address: 42
   - type: ConnectionCheckedOut
     connectionId: 1
     address: 42
+    duration: 42
 ignore:
   - ConnectionPoolCreated
   - ConnectionPoolReady
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkout-connection.json b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkout-connection.json
@@ -23,12 +23,14 @@
     {
       "type": "ConnectionReady",
       "connectionId": 1,
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckedOut",
       "connectionId": 1,
-      "address": 42
+      "address": 42,
+      "duration": 42
     }
   ],
   "ignore": [
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkout-connection.yml b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkout-connection.yml
@@ -13,9 +13,11 @@ events:
   - type: ConnectionReady
     connectionId: 1
     address: 42
+    duration: 42
   - type: ConnectionCheckedOut
     connectionId: 1
     address: 42
+    duration: 42
 ignore:
   - ConnectionPoolReady
   - ConnectionPoolCreated
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkout-error-closed.json b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkout-error-closed.json
@@ -38,7 +38,8 @@
     {
       "type": "ConnectionCheckedOut",
       "address": 42,
-      "connectionId": 42
+      "connectionId": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckedIn",
@@ -56,6 +57,7 @@
     {
       "type": "ConnectionCheckOutFailed",
       "address": 42,
+      "duration": 42,
       "reason": "poolClosed"
     }
   ],
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkout-error-closed.yml b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkout-error-closed.yml
@@ -21,6 +21,7 @@ events:
   - type: ConnectionCheckedOut
     address: 42
     connectionId: 42
+    duration: 42
   - type: ConnectionCheckedIn
     address: 42
     connectionId: 42
@@ -30,6 +31,7 @@ events:
     address: 42
   - type: ConnectionCheckOutFailed
     address: 42
+    duration: 42
     reason: poolClosed
 ignore:
   - ConnectionPoolReady
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkout-maxConnecting-timeout.json b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkout-maxConnecting-timeout.json
@@ -89,7 +89,8 @@
     {
       "type": "ConnectionCheckOutFailed",
       "reason": "timeout",
-      "address": 42
+      "address": 42,
+      "duration": 42
     }
   ],
   "ignore": [
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkout-maxConnecting-timeout.yml b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-checkout-maxConnecting-timeout.yml
@@ -60,6 +60,7 @@ events:
   - type: ConnectionCheckOutFailed
     reason: timeout
     address: 42
+    duration: 42
 ignore:
   - ConnectionCreated
   - ConnectionCheckedIn
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-clear-clears-waitqueue.json b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-clear-clears-waitqueue.json
@@ -59,7 +59,8 @@
     },
     {
       "type": "ConnectionCheckedOut",
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckOutStarted",
@@ -76,17 +77,20 @@
     {
       "type": "ConnectionCheckOutFailed",
       "reason": "connectionError",
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckOutFailed",
       "reason": "connectionError",
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckOutFailed",
       "reason": "connectionError",
-      "address": 42
+      "address": 42,
+      "duration": 42
     }
   ],
   "ignore": [
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-clear-clears-waitqueue.yml b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-clear-clears-waitqueue.yml
@@ -38,6 +38,7 @@ events:
     address: 42
   - type: ConnectionCheckedOut
     address: 42
+    duration: 42
   - type: ConnectionCheckOutStarted
     address: 42
   - type: ConnectionCheckOutStarted
@@ -47,12 +48,15 @@ events:
   - type: ConnectionCheckOutFailed
     reason: connectionError
     address: 42
+    duration: 42
   - type: ConnectionCheckOutFailed
     reason: connectionError
     address: 42
+    duration: 42
   - type: ConnectionCheckOutFailed
     reason: connectionError
     address: 42
+    duration: 42
 ignore:
   - ConnectionPoolReady
   - ConnectionPoolCleared
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-clear-ready.json b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-clear-ready.json
@@ -40,7 +40,8 @@
     {
       "type": "ConnectionCheckedOut",
       "address": 42,
-      "connectionId": 42
+      "connectionId": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionPoolCleared",
@@ -49,6 +50,7 @@
     {
       "type": "ConnectionCheckOutFailed",
       "address": 42,
+      "duration": 42,
       "reason": "connectionError"
     },
     {
@@ -57,7 +59,8 @@
     },
     {
       "type": "ConnectionCheckedOut",
-      "address": 42
+      "address": 42,
+      "duration": 42
     }
   ],
   "ignore": [
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-clear-ready.yml b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-clear-ready.yml
@@ -20,15 +20,18 @@ events:
   - type: ConnectionCheckedOut
     address: 42
     connectionId: 42
+    duration: 42
   - type: ConnectionPoolCleared
     address: 42
   - type: ConnectionCheckOutFailed
     address: 42
+    duration: 42
     reason: connectionError
   - type: ConnectionPoolReady
     address: 42
   - type: ConnectionCheckedOut
     address: 42
+    duration: 42
 ignore:
   - ConnectionPoolCreated
   - ConnectionReady
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-ready.json b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-ready.json
@@ -31,7 +31,8 @@
     {
       "type": "ConnectionCheckOutFailed",
       "reason": "connectionError",
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionPoolReady",
@@ -47,7 +48,8 @@
     },
     {
       "type": "ConnectionCheckedOut",
-      "address": 42
+      "address": 42,
+      "duration": 42
     }
   ],
   "ignore": [
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-ready.yml b/specifications/connection-monitoring-and-pooling/tests/cmap-format/pool-ready.yml
@@ -17,6 +17,7 @@ events:
   - type: ConnectionCheckOutFailed
     reason: connectionError
     address: 42
+    duration: 42
   - type: ConnectionPoolReady
     address: 42
   - type: ConnectionCheckOutStarted
@@ -25,6 +26,7 @@ events:
     address: 42
   - type: ConnectionCheckedOut
     address: 42
+    duration: 42
 ignore:
   - ConnectionPoolCreated
   - ConnectionReady
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/wait-queue-timeout.json b/specifications/connection-monitoring-and-pooling/tests/cmap-format/wait-queue-timeout.json
@@ -48,7 +48,8 @@
     {
       "type": "ConnectionCheckedOut",
       "connectionId": 42,
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckOutStarted",
@@ -57,7 +58,8 @@
     {
       "type": "ConnectionCheckOutFailed",
       "reason": "timeout",
-      "address": 42
+      "address": 42,
+      "duration": 42
     },
     {
       "type": "ConnectionCheckedIn",
diff --git a/specifications/connection-monitoring-and-pooling/tests/cmap-format/wait-queue-timeout.yml b/specifications/connection-monitoring-and-pooling/tests/cmap-format/wait-queue-timeout.yml
@@ -32,11 +32,13 @@ events:
   - type: ConnectionCheckedOut
     connectionId: 42
     address: 42
+    duration: 42
   - type: ConnectionCheckOutStarted
     address: 42
   - type: ConnectionCheckOutFailed
     reason: timeout
     address: 42
+    duration: 42
   - type: ConnectionCheckedIn
     connectionId: 42
     address: 42
diff --git a/src/MongoDB.Driver/Core/ConnectionPools/ExclusiveConnectionPool.Helpers.cs b/src/MongoDB.Driver/Core/ConnectionPools/ExclusiveConnectionPool.Helpers.cs
@@ -180,17 +180,15 @@ public AcquireConnectionHelper(ExclusiveConnectionPool pool)
 
             public IConnectionHandle AcquireConnection(CancellationToken cancellationToken)
             {
-                Stopwatch stopwatch = new();
+                var stopwatch = new Stopwatch();
                 try
                 {
-                    StartCheckingOut();
-
-                    stopwatch.Start();
+                    StartCheckingOut(stopwatch);
                     _poolQueueWaitResult = _pool._maxConnectionsQueue.WaitSignaled(_timeout, cancellationToken);
 
                     if (_poolQueueWaitResult == SemaphoreSlimSignalable.SemaphoreWaitResult.Entered)
                     {
-                        PooledConnection pooledConnection = null;
+                        PooledConnection pooledConnection;
                         var timeout = EnsureTimeout(stopwatch);
 
                         using (var connectionCreator = new ConnectionCreator(_pool, timeout))
@@ -214,17 +212,15 @@ public IConnectionHandle AcquireConnection(CancellationToken cancellationToken)
 
             public async Task<IConnectionHandle> AcquireConnectionAsync(CancellationToken cancellationToken)
             {
-                Stopwatch stopwatch = new();
+                var stopwatch = new Stopwatch();
                 try
                 {
-                    StartCheckingOut();
-
-                    stopwatch.Start();
+                    StartCheckingOut(stopwatch);
                     _poolQueueWaitResult = await _pool._maxConnectionsQueue.WaitSignaledAsync(_timeout, cancellationToken).ConfigureAwait(false);
 
                     if (_poolQueueWaitResult == SemaphoreSlimSignalable.SemaphoreWaitResult.Entered)
                     {
-                        PooledConnection pooledConnection = null;
+                        PooledConnection pooledConnection;
                         var timeout = EnsureTimeout(stopwatch);
 
                         using (var connectionCreator = new ConnectionCreator(_pool, timeout))
@@ -285,10 +281,11 @@ private void AcquireWaitQueueSlot()
                 _enteredWaitQueue = true;
             }
 
-            private void StartCheckingOut()
+            private void StartCheckingOut(Stopwatch stopwatch)
             {
                 _pool._eventLogger.LogAndPublish(new ConnectionPoolCheckingOutConnectionEvent(_pool._serverId, EventContext.OperationId));
 
+                stopwatch.Start();
                 _pool._poolState.ThrowIfNotReady();
 
                 AcquireWaitQueueSlot();
diff --git a/tests/MongoDB.Driver.TestHelpers/Core/MockConnection.cs b/tests/MongoDB.Driver.TestHelpers/Core/MockConnection.cs
@@ -147,7 +147,7 @@ public void Dispose()
         {
             _closingEventHandler?.Invoke(new ConnectionClosingEvent(_connectionId, EventContext.OperationId));
             IsExpired = true;
-            _closedEventHandler?.Invoke(new ConnectionClosedEvent(_connectionId, TimeSpan.Zero, EventContext.OperationId));
+            _closedEventHandler?.Invoke(new ConnectionClosedEvent(_connectionId, TimeSpan.FromTicks(1), EventContext.OperationId));
         }
 
         public void EnqueueCommandResponseMessage(Exception exception)
@@ -194,7 +194,7 @@ public void Open(CancellationToken cancellationToken)
             // which is one from methods called inside Open
             _lastUsedAtUtc = DateTime.UtcNow;
 
-            _openedEventHandler?.Invoke(new ConnectionOpenedEvent(_connectionId, _connectionSettings, TimeSpan.Zero, null));
+            _openedEventHandler?.Invoke(new ConnectionOpenedEvent(_connectionId, _connectionSettings, TimeSpan.FromTicks(1), null));
         }
 
         public Task OpenAsync(CancellationToken cancellationToken)
@@ -206,7 +206,7 @@ public Task OpenAsync(CancellationToken cancellationToken)
             // which is one from methods called inside OpenAsync
             _lastUsedAtUtc = DateTime.UtcNow;
 
-            _openedEventHandler?.Invoke(new ConnectionOpenedEvent(_connectionId, _connectionSettings, TimeSpan.Zero, null));
+            _openedEventHandler?.Invoke(new ConnectionOpenedEvent(_connectionId, _connectionSettings, TimeSpan.FromTicks(1), null));
 
             return Task.CompletedTask;
         }
diff --git a/tests/MongoDB.Driver.Tests/Specifications/connection-monitoring-and-pooling/ConnectionMonitoringAndPoolingTestRunner.cs b/tests/MongoDB.Driver.Tests/Specifications/connection-monitoring-and-pooling/ConnectionMonitoringAndPoolingTestRunner.cs

Original file line number	Diff line number	Diff line change
`@@ -22,7 +22,8 @@`
`22`	`22`	`{`
`23`	`23`	`"type": "ConnectionCheckedOut",`
`24`	`24`	`"connectionId": 1,`
`25`		`- "address": 42`
	`25`	`+ "address": 42,`
	`26`	`+ "duration": 42`
`26`	`27`	`},`
`27`	`28`	`{`
`28`	`29`	`"type": "ConnectionCheckedIn",`
`@@ -32,7 +33,8 @@`
`32`	`33`	`{`
`33`	`34`	`"type": "ConnectionCheckedOut",`
`34`	`35`	`"connectionId": 1,`
`35`		`- "address": 42`
	`36`	`+ "address": 42,`
	`37`	`+ "duration": 42`
`36`	`38`	`}`
`37`	`39`	`],`
`38`	`40`	`"ignore": [`
Original file line number	Diff line number	Diff line change
`@@ -23,12 +23,14 @@`
`23`	`23`	`{`
`24`	`24`	`"type": "ConnectionReady",`
`25`	`25`	`"connectionId": 1,`
`26`		`- "address": 42`
	`26`	`+ "address": 42,`
	`27`	`+ "duration": 42`
`27`	`28`	`},`
`28`	`29`	`{`
`29`	`30`	`"type": "ConnectionCheckedOut",`
`30`	`31`	`"connectionId": 1,`
`31`		`- "address": 42`
	`32`	`+ "address": 42,`
	`33`	`+ "duration": 42`
`32`	`34`	`}`
`33`	`35`	`],`
`34`	`36`	`"ignore": [`
Original file line number	Diff line number	Diff line change
`@@ -38,7 +38,8 @@`
`38`	`38`	`{`
`39`	`39`	`"type": "ConnectionCheckedOut",`
`40`	`40`	`"address": 42,`
`41`		`- "connectionId": 42`
	`41`	`+ "connectionId": 42,`
	`42`	`+ "duration": 42`
`42`	`43`	`},`
`43`	`44`	`{`
`44`	`45`	`"type": "ConnectionCheckedIn",`
`@@ -56,6 +57,7 @@`
`56`	`57`	`{`
`57`	`58`	`"type": "ConnectionCheckOutFailed",`
`58`	`59`	`"address": 42,`
	`60`	`+ "duration": 42,`
`59`	`61`	`"reason": "poolClosed"`
`60`	`62`	`}`
`61`	`63`	`],`
Original file line number	Diff line number	Diff line change
`@@ -89,7 +89,8 @@`
`89`	`89`	`{`
`90`	`90`	`"type": "ConnectionCheckOutFailed",`
`91`	`91`	`"reason": "timeout",`
`92`		`- "address": 42`
	`92`	`+ "address": 42,`
	`93`	`+ "duration": 42`
`93`	`94`	`}`
`94`	`95`	`],`
`95`	`96`	`"ignore": [`
Original file line number	Diff line number	Diff line change
`@@ -59,7 +59,8 @@`
`59`	`59`	`},`
`60`	`60`	`{`
`61`	`61`	`"type": "ConnectionCheckedOut",`
`62`		`- "address": 42`
	`62`	`+ "address": 42,`
	`63`	`+ "duration": 42`
`63`	`64`	`},`
`64`	`65`	`{`
`65`	`66`	`"type": "ConnectionCheckOutStarted",`
`@@ -76,17 +77,20 @@`
`76`	`77`	`{`
`77`	`78`	`"type": "ConnectionCheckOutFailed",`
`78`	`79`	`"reason": "connectionError",`
`79`		`- "address": 42`
	`80`	`+ "address": 42,`
	`81`	`+ "duration": 42`
`80`	`82`	`},`
`81`	`83`	`{`
`82`	`84`	`"type": "ConnectionCheckOutFailed",`
`83`	`85`	`"reason": "connectionError",`
`84`		`- "address": 42`
	`86`	`+ "address": 42,`
	`87`	`+ "duration": 42`
`85`	`88`	`},`
`86`	`89`	`{`
`87`	`90`	`"type": "ConnectionCheckOutFailed",`
`88`	`91`	`"reason": "connectionError",`
`89`		`- "address": 42`
	`92`	`+ "address": 42,`
	`93`	`+ "duration": 42`
`90`	`94`	`}`
`91`	`95`	`],`
`92`	`96`	`"ignore": [`