feat(NODE-5459): add durations to connection pool events

Author: aditi-khare-mongoDB

src/cmap/connection.ts

@@ -191,6 +191,7 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
 
   private lastUseTime: number;
   private clusterTime: Document | null = null;
+
   private error: Error | null = null;
   private dataEvents: AsyncGenerator<Buffer, void, void> | null = null;
 
@@ -229,6 +230,7 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
     this.description = new StreamDescription(this.address, options);
     this.generation = options.generation;
     this.lastUseTime = now();
+    this.connectionCreatedEventTime = null;
 
     this.messageStream = this.socket
       .on('error', this.onError.bind(this))

src/cmap/connection_pool.ts

@@ -629,6 +629,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
 
     this[kPending]++;
     // This is our version of a "virtual" no-I/O connection as the spec requires
+    const connectionCreatedTime = Date.now();
     this.emitAndLog(
       ConnectionPool.CONNECTION_CREATED,
       new ConnectionCreatedEvent(this, { id: connectOptions.id })
@@ -670,7 +671,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
         connection.markAvailable();
         this.emitAndLog(
           ConnectionPool.CONNECTION_READY,
-          new ConnectionReadyEvent(this, connection)
+          new ConnectionReadyEvent(this, connection, connectionCreatedTime)
         );
 
         this[kPending]--;

src/cmap/connection_pool_events.ts

@@ -126,12 +126,25 @@ export class ConnectionCreatedEvent extends ConnectionPoolMonitoringEvent {
 export class ConnectionReadyEvent extends ConnectionPoolMonitoringEvent {
   /** The id of the connection */
   connectionId: number | '<monitor>';
+  /**
+   * The time it took to establish the connection.
+   * In accordance with the definition of establishment of a connection
+   * specified by `ConnectionPoolOptions.maxConnecting`,
+   * it is the time elapsed between emitting a `ConnectionCreatedEvent`
+   * and emitting this event as part of the same checking out.
+   *
+   * Naturally, when establishing a connection is part of checking out,
+   * this duration is not greater than
+   * `ConnectionCheckedOutEvent.duration`.
+   */
+  durationMS: number;
   /** @internal */
   name = CONNECTION_READY;
 
   /** @internal */
-  constructor(pool: ConnectionPool, connection: Connection) {
+  constructor(pool: ConnectionPool, connection: Connection, connectionCreatedEventTime: number) {
     super(pool);
+    this.durationMS = Date.now() - connectionCreatedEventTime;
     this.connectionId = connection.id;
   }
 }
@@ -194,6 +207,20 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent
   error?: MongoError;
   /** @internal */
   name = CONNECTION_CHECK_OUT_FAILED;
+  /**
+   * The time it took to check out the connection.
+   * More specifically, the time elapsed between
+   * emitting a `ConnectionCheckOutStartedEvent`
+   * and emitting this event as part of the same checking out.
+   *
+   * Naturally, if a new connection was not created (`ConnectionCreatedEvent`)
+   * and established (`ConnectionReadyEvent`) as part of checking out,
+   * this duration is usually
+   * not greater than `ConnectionPoolOptions.waitQueueTimeoutMS`,
+   * but MAY occasionally be greater than that,
+   * because a driver does not provide hard real-time guarantees.
+   */
+  durationMS: number;
 
   /** @internal */
   constructor(
@@ -202,6 +229,7 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent
     error?: MongoError
   ) {
     super(pool);
+    this.durationMS = this.durationMS = Date.now() - (connection.connectionCreatedEventTime ?? Date.now());
     this.reason = reason;
     this.error = error;
   }
@@ -217,10 +245,25 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent {
   connectionId: number | '<monitor>';
   /** @internal */
   name = CONNECTION_CHECKED_OUT;
+  /**
+   * The time it took to check out the connection.
+   * More specifically, the time elapsed between
+   * emitting a `ConnectionCheckOutStartedEvent`
+   * and emitting this event as part of the same checking out.
+   *
+   * Naturally, if a new connection was not created (`ConnectionCreatedEvent`)
+   * and established (`ConnectionReadyEvent`) as part of checking out,
+   * this duration is usually
+   * not greater than `ConnectionPoolOptions.waitQueueTimeoutMS`,
+   * but MAY occasionally be greater than that,
+   * because a driver does not provide hard real-time guarantees.
+   */
+  durationMS: number;
 
   /** @internal */
   constructor(pool: ConnectionPool, connection: Connection) {
     super(pool);
+    this.durationMS = 0;
     this.connectionId = connection.id;
   }
 }

test/integration/connection-monitoring-and-pooling/connection_monitoring_and_pooling.spec.test.ts

@@ -39,7 +39,7 @@ const INTERRUPT_IN_USE_SKIPPED_TESTS: SkipDescription[] = [
   }
 ];
 
-describe('Connection Monitoring and Pooling Spec Tests (Integration) - cmap-format', function () {
+describe.only('Connection Monitoring and Pooling Spec Tests (Integration) - cmap-format', function () {
   const tests: CmapTest[] = loadSpecTests('connection-monitoring-and-pooling', 'cmap-format');
 
   runCmapTestSuite(tests, {
@@ -57,7 +57,7 @@ describe('Connection Monitoring and Pooling Spec Tests (Integration) - cmap-form
   });
 });
 
-describe('Connection Monitoring and Pooling Spec Tests (Integration) - logging', function () {
+describe.only('Connection Monitoring and Pooling Spec Tests (Integration) - logging', function () {
   const tests = loadSpecTests('connection-monitoring-and-pooling', 'logging');
 
   runUnifiedSuite(tests, test => {