CSHARP-4722: Add durations to connection pool events (#1177)

adelinowona · web-flow · commit 927c4453207c · 2023-10-04T15:58:53.000-04:00
diff --git a/specifications/connection-monitoring-and-pooling/connection-monitoring-and-pooling.rst b/specifications/connection-monitoring-and-pooling/connection-monitoring-and-pooling.rst
diff --git a/specifications/connection-monitoring-and-pooling/tests/logging/connection-logging.json b/specifications/connection-monitoring-and-pooling/tests/logging/connection-logging.json
@@ -140,6 +140,13 @@
                     "int",
                     "long"
                   ]
+                },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
                 }
               }
             },
@@ -162,6 +169,13 @@
                     "int",
                     "long"
                   ]
+                },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
                 }
               }
             },
@@ -421,6 +435,13 @@
                 "reason": "An error occurred while trying to establish a new connection",
                 "error": {
                   "$$exists": true
+                },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
                 }
               }
             }
diff --git a/specifications/connection-monitoring-and-pooling/tests/logging/connection-logging.yml b/specifications/connection-monitoring-and-pooling/tests/logging/connection-logging.yml
@@ -66,14 +66,16 @@ tests:
               driverConnectionId: { $$type: [int, long] }
               serverHost: { $$type: string }
               serverPort: { $$type: [int, long] }
-          
+              durationMS: { $$type: [double, int, long] }
+
           - level: debug
             component: connection
             data:
               message: "Connection checked out"
               driverConnectionId: { $$type: [int, long] }
               serverHost: { $$type: string }
               serverPort: { $$type: [int, long] }
+              durationMS: { $$type: [double, int, long] }
 
           - level: debug
             component: connection
@@ -194,3 +196,4 @@ tests:
               serverPort: { $$type: [int, long] }
               reason: "An error occurred while trying to establish a new connection"
               error: { $$exists: true }
+              durationMS: { $$type: [double, int, long] }
diff --git a/specifications/connection-monitoring-and-pooling/tests/logging/connection-pool-options.json b/specifications/connection-monitoring-and-pooling/tests/logging/connection-pool-options.json
@@ -1,5 +1,5 @@
 {
-  "description": "connection-logging",
+  "description": "connection-pool-options",
   "schemaVersion": "1.13",
   "runOnRequirements": [
     {
@@ -128,6 +128,13 @@
                     "int",
                     "long"
                   ]
+                },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
                 }
               }
             }
diff --git a/specifications/connection-monitoring-and-pooling/tests/logging/connection-pool-options.yml b/specifications/connection-monitoring-and-pooling/tests/logging/connection-pool-options.yml
@@ -1,4 +1,4 @@
-description: "connection-logging"
+description: "connection-pool-options"
 
 schemaVersion: "1.13"
 
@@ -71,6 +71,7 @@ tests:
               driverConnectionId: { $$type: [int, long] }
               serverHost: { $$type: string }
               serverPort: { $$type: [int, long] }
+              durationMS: { $$type: [double, int, long] }
 
   # Drivers who have not done DRIVERS-1943 will need to skip this test.
   - description: "maxConnecting should be included in connection pool created message when specified"
diff --git a/src/MongoDB.Driver.Core/Core/ConnectionPools/ExclusiveConnectionPool.Helpers.cs b/src/MongoDB.Driver.Core/Core/ConnectionPools/ExclusiveConnectionPool.Helpers.cs
@@ -180,11 +180,12 @@ public AcquireConnectionHelper(ExclusiveConnectionPool pool)
 
             public IConnectionHandle AcquireConnection(CancellationToken cancellationToken)
             {
+                Stopwatch stopwatch = new();
                 try
                 {
                     StartCheckingOut();
 
-                    var stopwatch = Stopwatch.StartNew();
+                    stopwatch.Start();
                     _poolQueueWaitResult = _pool._maxConnectionsQueue.WaitSignaled(_timeout, cancellationToken);
 
                     if (_poolQueueWaitResult == SemaphoreSlimSignalable.SemaphoreWaitResult.Entered)
@@ -205,18 +206,20 @@ public IConnectionHandle AcquireConnection(CancellationToken cancellationToken)
                 }
                 catch (Exception ex)
                 {
-                    HandleException(ex);
+                    stopwatch.Stop();
+                    HandleException(ex, stopwatch.Elapsed);
                     throw;
                 }
             }
 
             public async Task<IConnectionHandle> AcquireConnectionAsync(CancellationToken cancellationToken)
             {
+                Stopwatch stopwatch = new();
                 try
                 {
                     StartCheckingOut();
 
-                    var stopwatch = Stopwatch.StartNew();
+                    stopwatch.Start();
                     _poolQueueWaitResult = await _pool._maxConnectionsQueue.WaitSignaledAsync(_timeout, cancellationToken).ConfigureAwait(false);
 
                     if (_poolQueueWaitResult == SemaphoreSlimSignalable.SemaphoreWaitResult.Entered)
@@ -237,7 +240,8 @@ public async Task<IConnectionHandle> AcquireConnectionAsync(CancellationToken ca
                 }
                 catch (Exception ex)
                 {
-                    HandleException(ex);
+                    stopwatch.Stop();
+                    HandleException(ex, stopwatch.Elapsed);
                     throw;
                 }
             }
@@ -328,7 +332,7 @@ private Exception CreateException(Stopwatch stopwatch) =>
                     _ => new InvalidOperationException($"Invalid {_poolQueueWaitResult}.")
                 };
 
-            private void HandleException(Exception ex)
+            private void HandleException(Exception ex, TimeSpan elapsedTime)
             {
                 var reason = ex switch
                 {
@@ -337,7 +341,7 @@ private void HandleException(Exception ex)
                     _ => ConnectionCheckOutFailedReason.ConnectionError
                 };
 
-                _pool._eventLogger.LogAndPublish(new ConnectionPoolCheckingOutConnectionFailedEvent(_pool._serverId, ex, EventContext.OperationId, reason));
+                _pool._eventLogger.LogAndPublish(new ConnectionPoolCheckingOutConnectionFailedEvent(_pool._serverId, ex, EventContext.OperationId, elapsedTime, reason));
             }
         }
 
diff --git a/src/MongoDB.Driver.Core/Core/Events/ConnectionPoolCheckingOutConnectionFailedEvent.cs b/src/MongoDB.Driver.Core/Core/Events/ConnectionPoolCheckingOutConnectionFailedEvent.cs
@@ -29,24 +29,28 @@ public struct ConnectionPoolCheckingOutConnectionFailedEvent : IEvent
         private readonly Exception _exception;
         private readonly long? _operationId;
         private readonly DateTime _timestamp;
+        private readonly TimeSpan _duration;
 
         /// <summary>
         /// Initializes a new instance of the <see cref="ConnectionPoolCheckingOutConnectionFailedEvent" /> struct.
         /// </summary>
         /// <param name="serverId">The server identifier.</param>
         /// <param name="exception">The exception.</param>
         /// <param name="operationId">The operation identifier.</param>
+        /// <param name="duration">The duration of time it took trying to check out the connection.</param>
         /// <param name="reason">The reason the checkout failed.</param>
         public ConnectionPoolCheckingOutConnectionFailedEvent(
             ServerId serverId,
             Exception exception,
             long? operationId,
+            TimeSpan duration,
             ConnectionCheckOutFailedReason reason)
         {
             _serverId = serverId;
             _exception = exception;
             _operationId = operationId;
             _reason = reason;
+            _duration = duration;
             _timestamp = DateTime.UtcNow;
         }
 
@@ -90,6 +94,14 @@ public ServerId ServerId
             get { return _serverId; }
         }
 
+        /// <summary>
+        /// Gets the duration of time it took trying to check out the connection.
+        /// </summary>
+        public TimeSpan Duration
+        {
+            get { return _duration; }
+        }
+
         /// <summary>
         /// Gets the timestamp.
         /// </summary>
diff --git a/src/MongoDB.Driver.Core/Core/Logging/StructuredLogTemplateProviders.cs b/src/MongoDB.Driver.Core/Core/Logging/StructuredLogTemplateProviders.cs
@@ -141,6 +141,13 @@ public static object[] GetParams(ServerId serverId, object arg1, object arg2, ob
             return new[] { serverId.ClusterId.Value, host, port, arg1, arg2, arg3 };
         }
 
+        public static object[] GetParams(ServerId serverId, object arg1, object arg2, object arg3, object arg4)
+        {
+            var (host, port) = serverId.EndPoint.GetHostAndPort();
+
+            return new[] { serverId.ClusterId.Value, host, port, arg1, arg2, arg3, arg4 };
+        }
+
         public static object[] GetParams(ServerId serverId, object arg1, object arg2, object arg3, object arg4, object arg5, object arg6)
         {
             var (host, port) = serverId.EndPoint.GetHostAndPort();
diff --git a/src/MongoDB.Driver.Core/Core/Logging/StructuredLogTemplateProvidersCmap.cs b/src/MongoDB.Driver.Core/Core/Logging/StructuredLogTemplateProvidersCmap.cs
@@ -55,17 +55,18 @@ private static void AddCmapTemplates()
 
             AddTemplateProvider<ConnectionPoolCheckedOutConnectionEvent>(
                 LogLevel.Debug,
-                ConnectionCommonParams(),
-                (e, _) => GetParams(e.ConnectionId, "Connection checked out"));
+                ConnectionCommonParams(DurationMS),
+                (e, _) => GetParams(e.ConnectionId, "Connection checked out", e.Duration.TotalMilliseconds));
 
             AddTemplateProvider<ConnectionPoolCheckingOutConnectionFailedEvent>(
                 LogLevel.Debug,
-                CmapCommonParams(Reason, Error),
+                CmapCommonParams(Reason, Error, DurationMS),
                 (e, o) => GetParams(
                     e.ServerId,
                     "Connection checkout failed",
                     GetCheckoutFailedReason(e.Reason),
-                    FormatException(e.Exception, o)));
+                    FormatException(e.Exception, o),
+                    e.Duration.TotalMilliseconds));
 
             AddTemplateProvider<ConnectionPoolRemovingConnectionEvent>(
                 LogLevel.Debug,
diff --git a/src/MongoDB.Driver.Core/Core/Logging/StructuredLogTemplateProvidersConnection.cs b/src/MongoDB.Driver.Core/Core/Logging/StructuredLogTemplateProvidersConnection.cs
@@ -41,8 +41,8 @@ private static void AddConnectionTemplates()
 
             AddTemplateProvider<ConnectionOpenedEvent>(
                  LogLevel.Debug,
-                 ConnectionCommonParams(),
-                 (e, _) => GetParams(e.ConnectionId, "Connection ready"));
+                 ConnectionCommonParams(DurationMS),
+                 (e, _) => GetParams(e.ConnectionId, "Connection ready", e.Duration.TotalMilliseconds));
 
             AddTemplateProvider<ConnectionOpeningEvent>(
                 LogLevel.Debug,

Original file line number	Diff line number	Diff line change
`@@ -140,6 +140,13 @@`
`140`	`140`	`"int",`
`141`	`141`	`"long"`
`142`	`142`	`]`
	`143`	`+ },`
	`144`	`+ "durationMS": {`
	`145`	`+ "$$type": [`
	`146`	`+ "double",`
	`147`	`+ "int",`
	`148`	`+ "long"`
	`149`	`+ ]`
`143`	`150`	`}`
`144`	`151`	`}`
`145`	`152`	`},`
`@@ -162,6 +169,13 @@`
`162`	`169`	`"int",`
`163`	`170`	`"long"`
`164`	`171`	`]`
	`172`	`+ },`
	`173`	`+ "durationMS": {`
	`174`	`+ "$$type": [`
	`175`	`+ "double",`
	`176`	`+ "int",`
	`177`	`+ "long"`
	`178`	`+ ]`
`165`	`179`	`}`
`166`	`180`	`}`
`167`	`181`	`},`
`@@ -421,6 +435,13 @@`
`421`	`435`	`"reason": "An error occurred while trying to establish a new connection",`
`422`	`436`	`"error": {`
`423`	`437`	`"$$exists": true`
	`438`	`+ },`
	`439`	`+ "durationMS": {`
	`440`	`+ "$$type": [`
	`441`	`+ "double",`
	`442`	`+ "int",`
	`443`	`+ "long"`
	`444`	`+ ]`
`424`	`445`	`}`
`425`	`446`	`}`
`426`	`447`	`}`
Original file line number	Diff line number	Diff line change
`@@ -1,5 +1,5 @@`
`1`	`1`	`{`
`2`		`- "description": "connection-logging",`
	`2`	`+ "description": "connection-pool-options",`
`3`	`3`	`"schemaVersion": "1.13",`
`4`	`4`	`"runOnRequirements": [`
`5`	`5`	`{`
`@@ -128,6 +128,13 @@`
`128`	`128`	`"int",`
`129`	`129`	`"long"`
`130`	`130`	`]`
	`131`	`+ },`
	`132`	`+ "durationMS": {`
	`133`	`+ "$$type": [`
	`134`	`+ "double",`
	`135`	`+ "int",`
	`136`	`+ "long"`
	`137`	`+ ]`
`131`	`138`	`}`
`132`	`139`	`}`
`133`	`140`	`}`
Original file line number	Diff line number	Diff line change
`@@ -180,11 +180,12 @@ public AcquireConnectionHelper(ExclusiveConnectionPool pool)`
`180`	`180`
`181`	`181`	`public IConnectionHandle AcquireConnection(CancellationToken cancellationToken)`
`182`	`182`	`{`
	`183`	`+ Stopwatch stopwatch = new();`
`183`	`184`	`try`
`184`	`185`	`{`
`185`	`186`	`StartCheckingOut();`
`186`	`187`
`187`		`- var stopwatch = Stopwatch.StartNew();`
	`188`	`+ stopwatch.Start();`
`188`	`189`	`_poolQueueWaitResult = _pool._maxConnectionsQueue.WaitSignaled(_timeout, cancellationToken);`
`189`	`190`
`190`	`191`	`if (_poolQueueWaitResult == SemaphoreSlimSignalable.SemaphoreWaitResult.Entered)`
`@@ -205,18 +206,20 @@ public IConnectionHandle AcquireConnection(CancellationToken cancellationToken)`
`205`	`206`	`}`
`206`	`207`	`catch (Exception ex)`
`207`	`208`	`{`
`208`		`- HandleException(ex);`
	`209`	`+ stopwatch.Stop();`
	`210`	`+ HandleException(ex, stopwatch.Elapsed);`
`209`	`211`	`throw;`
`210`	`212`	`}`
`211`	`213`	`}`
`212`	`214`
`213`	`215`	`public async Task<IConnectionHandle> AcquireConnectionAsync(CancellationToken cancellationToken)`
`214`	`216`	`{`
	`217`	`+ Stopwatch stopwatch = new();`
`215`	`218`	`try`
`216`	`219`	`{`
`217`	`220`	`StartCheckingOut();`
`218`	`221`
`219`		`- var stopwatch = Stopwatch.StartNew();`
	`222`	`+ stopwatch.Start();`
`220`	`223`	`_poolQueueWaitResult = await _pool._maxConnectionsQueue.WaitSignaledAsync(_timeout, cancellationToken).ConfigureAwait(false);`
`221`	`224`
`222`	`225`	`if (_poolQueueWaitResult == SemaphoreSlimSignalable.SemaphoreWaitResult.Entered)`
`@@ -237,7 +240,8 @@ public async Task<IConnectionHandle> AcquireConnectionAsync(CancellationToken ca`
`237`	`240`	`}`
`238`	`241`	`catch (Exception ex)`
`239`	`242`	`{`
`240`		`- HandleException(ex);`
	`243`	`+ stopwatch.Stop();`
	`244`	`+ HandleException(ex, stopwatch.Elapsed);`
`241`	`245`	`throw;`
`242`	`246`	`}`
`243`	`247`	`}`
`@@ -328,7 +332,7 @@ private Exception CreateException(Stopwatch stopwatch) =>`
`328`	`332`	`_ => new InvalidOperationException($"Invalid {_poolQueueWaitResult}.")`
`329`	`333`	`};`
`330`	`334`
`331`		`- private void HandleException(Exception ex)`
	`335`	`+ private void HandleException(Exception ex, TimeSpan elapsedTime)`
`332`	`336`	`{`
`333`	`337`	`var reason = ex switch`
`334`	`338`	`{`
`@@ -337,7 +341,7 @@ private void HandleException(Exception ex)`
`337`	`341`	`_ => ConnectionCheckOutFailedReason.ConnectionError`
`338`	`342`	`};`
`339`	`343`
`340`		`- _pool._eventLogger.LogAndPublish(new ConnectionPoolCheckingOutConnectionFailedEvent(_pool._serverId, ex, EventContext.OperationId, reason));`
	`344`	`+ _pool._eventLogger.LogAndPublish(new ConnectionPoolCheckingOutConnectionFailedEvent(_pool._serverId, ex, EventContext.OperationId, elapsedTime, reason));`
`341`	`345`	`}`
`342`	`346`	`}`
`343`	`347`
Original file line number	Diff line number	Diff line change
`@@ -141,6 +141,13 @@ public static object[] GetParams(ServerId serverId, object arg1, object arg2, ob`
`141`	`141`	`return new[] { serverId.ClusterId.Value, host, port, arg1, arg2, arg3 };`
`142`	`142`	`}`
`143`	`143`
	`144`	`+ public static object[] GetParams(ServerId serverId, object arg1, object arg2, object arg3, object arg4)`
	`145`	`+ {`
	`146`	`+ var (host, port) = serverId.EndPoint.GetHostAndPort();`
	`147`	`+`
	`148`	`+ return new[] { serverId.ClusterId.Value, host, port, arg1, arg2, arg3, arg4 };`
	`149`	`+ }`
	`150`	`+`
`144`	`151`	`public static object[] GetParams(ServerId serverId, object arg1, object arg2, object arg3, object arg4, object arg5, object arg6)`
`145`	`152`	`{`
`146`	`153`	`var (host, port) = serverId.EndPoint.GetHostAndPort();`