GODRIVER-2910 Add durations to connection pool events. (#1590)

matthewdale · web-flow · commit 94dfdff4e3bf · 2024-04-09T15:10:20.000-07:00
diff --git a/event/monitoring.go b/event/monitoring.go
@@ -117,6 +117,7 @@ type PoolEvent struct {
 	Address      string              `json:"address"`
 	ConnectionID uint64              `json:"connectionId"`
 	PoolOptions  *MonitorPoolOptions `json:"options"`
+	Duration     time.Duration       `json:"duration"`
 	Reason       string              `json:"reason"`
 	// ServiceID is only set if the Type is PoolCleared and the server is deployed behind a load balancer. This field
 	// can be used to distinguish between individual servers in a load balanced deployment.
diff --git a/testdata/connection-monitoring-and-pooling/logging/connection-logging.json b/testdata/connection-monitoring-and-pooling/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"
+                  ]
                 }
               }
             },
@@ -222,6 +236,13 @@
                     "int",
                     "long"
                   ]
+                },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
                 }
               }
             },
@@ -444,7 +465,7 @@
             {
               "level": "debug",
               "component": "connection",
-	      "unordered": true,
+              "unordered": true,
               "data": {
                 "message": "Connection closed",
                 "driverConnectionId": {
@@ -471,7 +492,7 @@
             {
               "level": "debug",
               "component": "connection",
-	      "unordered": true,
+              "unordered": true,
               "data": {
                 "message": "Connection checkout failed",
                 "serverHost": {
@@ -486,6 +507,13 @@
                 "reason": "An error occurred while trying to establish a new connection",
                 "error": {
                   "$$exists": true
+                },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
                 }
               }
             }
diff --git a/testdata/connection-monitoring-and-pooling/logging/connection-logging.yml b/testdata/connection-monitoring-and-pooling/logging/connection-logging.yml
@@ -66,6 +66,7 @@ tests:
               driverConnectionId: { $$type: [int, long] }
               serverHost: { $$type: string }
               serverPort: { $$type: [int, long] }
+              durationMS: { $$type: [double, int, long] }
 
           - level: debug
             component: connection
@@ -74,6 +75,7 @@ tests:
               driverConnectionId: { $$type: [int, long] }
               serverHost: { $$type: string }
               serverPort: { $$type: [int, long] }
+              durationMS: { $$type: [double, int, long] }
 
           - level: debug
             component: connection
@@ -98,6 +100,7 @@ tests:
               driverConnectionId: { $$type: [int, long] }
               serverHost: { $$type: string }
               serverPort: { $$type: [int, long] }
+              durationMS: { $$type: [double, int, long] }
 
           - level: debug
             component: connection
@@ -219,4 +222,5 @@ tests:
               serverPort: { $$type: [int, long] }
               reason: "An error occurred while trying to establish a new connection"
               error: { $$exists: true }
+              durationMS: { $$type: [double, int, long] }
               unordered: true
diff --git a/testdata/connection-monitoring-and-pooling/logging/connection-pool-options.json b/testdata/connection-monitoring-and-pooling/logging/connection-pool-options.json
@@ -1,5 +1,5 @@
 {
-  "description": "connection-pool-logging",
+  "description": "connection-pool-options",
   "schemaVersion": "1.13",
   "runOnRequirements": [
     {
@@ -128,6 +128,13 @@
                     "int",
                     "long"
                   ]
+                },
+                "durationMS": {
+                  "$$type": [
+                    "double",
+                    "int",
+                    "long"
+                  ]
                 }
               }
             }
diff --git a/testdata/connection-monitoring-and-pooling/logging/connection-pool-options.yml b/testdata/connection-monitoring-and-pooling/logging/connection-pool-options.yml
@@ -1,4 +1,4 @@
-description: "connection-pool-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/x/mongo/driver/topology/pool.go b/x/mongo/driver/topology/pool.go
@@ -467,6 +467,7 @@ func (p *pool) checkOut(ctx context.Context) (conn *connection, err error) {
 		})
 	}
 
+	start := time.Now()
 	// Check the pool state while holding a stateMu read lock. If the pool state is not "ready",
 	// return an error. Do all of this while holding the stateMu read lock to prevent a state change between
 	// checking the state and entering the wait queue. Not holding the stateMu read lock here may
@@ -477,8 +478,10 @@ func (p *pool) checkOut(ctx context.Context) (conn *connection, err error) {
 	case poolClosed:
 		p.stateMu.RUnlock()
 
+		duration := time.Since(start)
 		if mustLogPoolMessage(p) {
 			keysAndValues := logger.KeyValues{
+				logger.KeyDurationMS, duration.Milliseconds(),
 				logger.KeyReason, logger.ReasonConnCheckoutFailedPoolClosed,
 			}
 
@@ -487,18 +490,21 @@ func (p *pool) checkOut(ctx context.Context) (conn *connection, err error) {
 
 		if p.monitor != nil {
 			p.monitor.Event(&event.PoolEvent{
-				Type:    event.GetFailed,
-				Address: p.address.String(),
-				Reason:  event.ReasonPoolClosed,
+				Type:     event.GetFailed,
+				Address:  p.address.String(),
+				Duration: duration,
+				Reason:   event.ReasonPoolClosed,
 			})
 		}
 		return nil, ErrPoolClosed
 	case poolPaused:
 		err := poolClearedError{err: p.lastClearErr, address: p.address}
 		p.stateMu.RUnlock()
 
+		duration := time.Since(start)
 		if mustLogPoolMessage(p) {
 			keysAndValues := logger.KeyValues{
+				logger.KeyDurationMS, duration.Milliseconds(),
 				logger.KeyReason, logger.ReasonConnCheckoutFailedError,
 			}
 
@@ -507,10 +513,11 @@ func (p *pool) checkOut(ctx context.Context) (conn *connection, err error) {
 
 		if p.monitor != nil {
 			p.monitor.Event(&event.PoolEvent{
-				Type:    event.GetFailed,
-				Address: p.address.String(),
-				Reason:  event.ReasonConnectionErrored,
-				Error:   err,
+				Type:     event.GetFailed,
+				Address:  p.address.String(),
+				Duration: duration,
+				Reason:   event.ReasonConnectionErrored,
+				Error:    err,
 			})
 		}
 		return nil, err
@@ -539,9 +546,11 @@ func (p *pool) checkOut(ctx context.Context) (conn *connection, err error) {
 		// or an error, so unlock the stateMu lock here.
 		p.stateMu.RUnlock()
 
+		duration := time.Since(start)
 		if w.err != nil {
 			if mustLogPoolMessage(p) {
 				keysAndValues := logger.KeyValues{
+					logger.KeyDurationMS, duration.Milliseconds(),
 					logger.KeyReason, logger.ReasonConnCheckoutFailedError,
 				}
 
@@ -550,18 +559,21 @@ func (p *pool) checkOut(ctx context.Context) (conn *connection, err error) {
 
 			if p.monitor != nil {
 				p.monitor.Event(&event.PoolEvent{
-					Type:    event.GetFailed,
-					Address: p.address.String(),
-					Reason:  event.ReasonConnectionErrored,
-					Error:   w.err,
+					Type:     event.GetFailed,
+					Address:  p.address.String(),
+					Duration: duration,
+					Reason:   event.ReasonConnectionErrored,
+					Error:    w.err,
 				})
 			}
 			return nil, w.err
 		}
 
+		duration = time.Since(start)
 		if mustLogPoolMessage(p) {
 			keysAndValues := logger.KeyValues{
 				logger.KeyDriverConnectionID, w.conn.driverConnectionID,
+				logger.KeyDurationMS, duration.Milliseconds(),
 			}
 
 			logPoolMessage(p, logger.ConnectionCheckedOut, keysAndValues...)
@@ -572,6 +584,7 @@ func (p *pool) checkOut(ctx context.Context) (conn *connection, err error) {
 				Type:         event.GetSucceeded,
 				Address:      p.address.String(),
 				ConnectionID: w.conn.driverConnectionID,
+				Duration:     duration,
 			})
 		}
 
@@ -584,12 +597,14 @@ func (p *pool) checkOut(ctx context.Context) (conn *connection, err error) {
 	p.stateMu.RUnlock()
 
 	// Wait for either the wantConn to be ready or for the Context to time out.
-	start := time.Now()
+	waitQueueStart := time.Now()
 	select {
 	case <-w.ready:
 		if w.err != nil {
+			duration := time.Since(start)
 			if mustLogPoolMessage(p) {
 				keysAndValues := logger.KeyValues{
+					logger.KeyDurationMS, duration.Milliseconds(),
 					logger.KeyReason, logger.ReasonConnCheckoutFailedError,
 					logger.KeyError, w.err.Error(),
 				}
@@ -599,19 +614,22 @@ func (p *pool) checkOut(ctx context.Context) (conn *connection, err error) {
 
 			if p.monitor != nil {
 				p.monitor.Event(&event.PoolEvent{
-					Type:    event.GetFailed,
-					Address: p.address.String(),
-					Reason:  event.ReasonConnectionErrored,
-					Error:   w.err,
+					Type:     event.GetFailed,
+					Address:  p.address.String(),
+					Duration: duration,
+					Reason:   event.ReasonConnectionErrored,
+					Error:    w.err,
 				})
 			}
 
 			return nil, w.err
 		}
 
+		duration := time.Since(start)
 		if mustLogPoolMessage(p) {
 			keysAndValues := logger.KeyValues{
 				logger.KeyDriverConnectionID, w.conn.driverConnectionID,
+				logger.KeyDurationMS, duration.Milliseconds(),
 			}
 
 			logPoolMessage(p, logger.ConnectionCheckedOut, keysAndValues...)
@@ -622,14 +640,17 @@ func (p *pool) checkOut(ctx context.Context) (conn *connection, err error) {
 				Type:         event.GetSucceeded,
 				Address:      p.address.String(),
 				ConnectionID: w.conn.driverConnectionID,
+				Duration:     duration,
 			})
 		}
 		return w.conn, nil
 	case <-ctx.Done():
-		duration := time.Since(start)
+		waitQueueDuration := time.Since(waitQueueStart)
 
+		duration := time.Since(start)
 		if mustLogPoolMessage(p) {
 			keysAndValues := logger.KeyValues{
+				logger.KeyDurationMS, duration.Milliseconds(),
 				logger.KeyReason, logger.ReasonConnCheckoutFailedTimout,
 			}
 
@@ -638,10 +659,11 @@ func (p *pool) checkOut(ctx context.Context) (conn *connection, err error) {
 
 		if p.monitor != nil {
 			p.monitor.Event(&event.PoolEvent{
-				Type:    event.GetFailed,
-				Address: p.address.String(),
-				Reason:  event.ReasonTimedOut,
-				Error:   ctx.Err(),
+				Type:     event.GetFailed,
+				Address:  p.address.String(),
+				Duration: duration,
+				Reason:   event.ReasonTimedOut,
+				Error:    ctx.Err(),
 			})
 		}
 
@@ -650,7 +672,7 @@ func (p *pool) checkOut(ctx context.Context) (conn *connection, err error) {
 			maxPoolSize:          p.maxSize,
 			totalConnections:     p.totalConnectionCount(),
 			availableConnections: p.availableConnectionCount(),
-			waitDuration:         duration,
+			waitDuration:         waitQueueDuration,
 		}
 		if p.loadBalanced {
 			err.pinnedConnections = &pinnedConnections{
@@ -1085,6 +1107,7 @@ func (p *pool) createConnections(ctx context.Context, wg *sync.WaitGroup) {
 			})
 		}
 
+		start := time.Now()
 		// Pass the createConnections context to connect to allow pool close to cancel connection
 		// establishment so shutdown doesn't block indefinitely if connectTimeout=0.
 		err := conn.connect(ctx)
@@ -1111,9 +1134,11 @@ func (p *pool) createConnections(ctx context.Context, wg *sync.WaitGroup) {
 			continue
 		}
 
+		duration := time.Since(start)
 		if mustLogPoolMessage(p) {
 			keysAndValues := logger.KeyValues{
 				logger.KeyDriverConnectionID, conn.driverConnectionID,
+				logger.KeyDurationMS, duration.Milliseconds(),
 			}
 
 			logPoolMessage(p, logger.ConnectionReady, keysAndValues...)
@@ -1124,6 +1149,7 @@ func (p *pool) createConnections(ctx context.Context, wg *sync.WaitGroup) {
 				Type:         event.ConnectionReady,
 				Address:      p.address.String(),
 				ConnectionID: conn.driverConnectionID,
+				Duration:     duration,
 			})
 		}
 
diff --git a/x/mongo/driver/topology/pool_test.go b/x/mongo/driver/topology/pool_test.go

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`	`},`
`@@ -222,6 +236,13 @@`
`222`	`236`	`"int",`
`223`	`237`	`"long"`
`224`	`238`	`]`
	`239`	`+ },`
	`240`	`+ "durationMS": {`
	`241`	`+ "$$type": [`
	`242`	`+ "double",`
	`243`	`+ "int",`
	`244`	`+ "long"`
	`245`	`+ ]`
`225`	`246`	`}`
`226`	`247`	`}`
`227`	`248`	`},`
`@@ -444,7 +465,7 @@`
`444`	`465`	`{`
`445`	`466`	`"level": "debug",`
`446`	`467`	`"component": "connection",`
`447`		`- "unordered": true,`
	`468`	`+ "unordered": true,`
`448`	`469`	`"data": {`
`449`	`470`	`"message": "Connection closed",`
`450`	`471`	`"driverConnectionId": {`
`@@ -471,7 +492,7 @@`
`471`	`492`	`{`
`472`	`493`	`"level": "debug",`
`473`	`494`	`"component": "connection",`
`474`		`- "unordered": true,`
	`495`	`+ "unordered": true,`
`475`	`496`	`"data": {`
`476`	`497`	`"message": "Connection checkout failed",`
`477`	`498`	`"serverHost": {`
`@@ -486,6 +507,13 @@`
`486`	`507`	`"reason": "An error occurred while trying to establish a new connection",`
`487`	`508`	`"error": {`
`488`	`509`	`"$$exists": true`
	`510`	`+ },`
	`511`	`+ "durationMS": {`
	`512`	`+ "$$type": [`
	`513`	`+ "double",`
	`514`	`+ "int",`
	`515`	`+ "long"`
	`516`	`+ ]`
`489`	`517`	`}`
`490`	`518`	`}`
`491`	`519`	`}`
Original file line number	Diff line number	Diff line change
`@@ -1,5 +1,5 @@`
`1`	`1`	`{`
`2`		`- "description": "connection-pool-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`	`}`