Skip to content

Commit 7295695

Browse files
aditi-khare-mongoDBnbbeeken
aditi-khare-mongoDB
and
nbbeeken
authored
feat(NODE-5459): add durations to connection pool events (mongodb#4166)
Co-authored-by: Neal Beeken <[email protected]>
1 parent fb442ed commit 7295695

File tree

9 files changed

+101
-11
lines changed

9 files changed

+101
-11
lines changed

‎src/cmap/connection_pool.ts‎

Lines changed: 17 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,7 @@ import {
2727
import { CancellationToken, TypedEventEmitter } from '../mongo_types';
2828
import type { Server } from '../sdam/server';
2929
import { Timeout, TimeoutError } from '../timeout';
30-
import { type Callback, List, makeCounter, promiseWithResolvers } from '../utils';
30+
import { type Callback, List, makeCounter, now, promiseWithResolvers } from '../utils';
3131
import { connect } from './connect';
3232
import { Connection, type ConnectionEvents, type ConnectionOptions } from './connection';
3333
import {
@@ -104,6 +104,7 @@ export interface WaitQueueMember {
104104
reject: (err: AnyError) => void;
105105
timeout: Timeout;
106106
[kCancelled]?: boolean;
107+
checkoutTime: number;
107108
}
108109

109110
/** @internal */
@@ -355,6 +356,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
355356
* explicitly destroyed by the new owner.
356357
*/
357358
async checkOut(): Promise<Connection> {
359+
const checkoutTime = now();
358360
this.emitAndLog(
359361
ConnectionPool.CONNECTION_CHECK_OUT_STARTED,
360362
new ConnectionCheckOutStartedEvent(this)
@@ -369,7 +371,8 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
369371
const waitQueueMember: WaitQueueMember = {
370372
resolve,
371373
reject,
372-
timeout
374+
timeout,
375+
checkoutTime
373376
};
374377

375378
this[kWaitQueue].push(waitQueueMember);
@@ -385,7 +388,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
385388

386389
this.emitAndLog(
387390
ConnectionPool.CONNECTION_CHECK_OUT_FAILED,
388-
new ConnectionCheckOutFailedEvent(this, 'timeout')
391+
new ConnectionCheckOutFailedEvent(this, 'timeout', waitQueueMember.checkoutTime)
389392
);
390393
const timeoutError = new WaitQueueTimeoutError(
391394
this.loadBalanced
@@ -629,6 +632,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
629632

630633
this[kPending]++;
631634
// This is our version of a "virtual" no-I/O connection as the spec requires
635+
const connectionCreatedTime = now();
632636
this.emitAndLog(
633637
ConnectionPool.CONNECTION_CREATED,
634638
new ConnectionCreatedEvent(this, { id: connectOptions.id })
@@ -670,7 +674,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
670674
connection.markAvailable();
671675
this.emitAndLog(
672676
ConnectionPool.CONNECTION_READY,
673-
new ConnectionReadyEvent(this, connection)
677+
new ConnectionReadyEvent(this, connection, connectionCreatedTime)
674678
);
675679

676680
this[kPending]--;
@@ -759,7 +763,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
759763
const error = this.closed ? new PoolClosedError(this) : new PoolClearedError(this);
760764
this.emitAndLog(
761765
ConnectionPool.CONNECTION_CHECK_OUT_FAILED,
762-
new ConnectionCheckOutFailedEvent(this, reason, error)
766+
new ConnectionCheckOutFailedEvent(this, reason, waitQueueMember.checkoutTime, error)
763767
);
764768
waitQueueMember.timeout.clear();
765769
this[kWaitQueue].shift();
@@ -780,7 +784,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
780784
this[kCheckedOut].add(connection);
781785
this.emitAndLog(
782786
ConnectionPool.CONNECTION_CHECKED_OUT,
783-
new ConnectionCheckedOutEvent(this, connection)
787+
new ConnectionCheckedOutEvent(this, connection, waitQueueMember.checkoutTime)
784788
);
785789
waitQueueMember.timeout.clear();
786790

@@ -809,14 +813,19 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
809813
this.emitAndLog(
810814
ConnectionPool.CONNECTION_CHECK_OUT_FAILED,
811815
// TODO(NODE-5192): Remove this cast
812-
new ConnectionCheckOutFailedEvent(this, 'connectionError', err as MongoError)
816+
new ConnectionCheckOutFailedEvent(
817+
this,
818+
'connectionError',
819+
waitQueueMember.checkoutTime,
820+
err as MongoError
821+
)
813822
);
814823
waitQueueMember.reject(err);
815824
} else if (connection) {
816825
this[kCheckedOut].add(connection);
817826
this.emitAndLog(
818827
ConnectionPool.CONNECTION_CHECKED_OUT,
819-
new ConnectionCheckedOutEvent(this, connection)
828+
new ConnectionCheckedOutEvent(this, connection, waitQueueMember.checkoutTime)
820829
);
821830
waitQueueMember.resolve(connection);
822831
}

‎src/cmap/connection_pool_events.ts‎

Lines changed: 34 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@ import {
1313
CONNECTION_READY
1414
} from '../constants';
1515
import type { MongoError } from '../error';
16+
import { now } from '../utils';
1617
import type { Connection } from './connection';
1718
import type { ConnectionPool, ConnectionPoolOptions } from './connection_pool';
1819

@@ -126,12 +127,25 @@ export class ConnectionCreatedEvent extends ConnectionPoolMonitoringEvent {
126127
export class ConnectionReadyEvent extends ConnectionPoolMonitoringEvent {
127128
/** The id of the connection */
128129
connectionId: number | '<monitor>';
130+
/**
131+
* The time it took to establish the connection.
132+
* In accordance with the definition of establishment of a connection
133+
* specified by `ConnectionPoolOptions.maxConnecting`,
134+
* it is the time elapsed between emitting a `ConnectionCreatedEvent`
135+
* and emitting this event as part of the same checking out.
136+
*
137+
* Naturally, when establishing a connection is part of checking out,
138+
* this duration is not greater than
139+
* `ConnectionCheckedOutEvent.duration`.
140+
*/
141+
durationMS: number;
129142
/** @internal */
130143
name = CONNECTION_READY;
131144

132145
/** @internal */
133-
constructor(pool: ConnectionPool, connection: Connection) {
146+
constructor(pool: ConnectionPool, connection: Connection, connectionCreatedEventTime: number) {
134147
super(pool);
148+
this.durationMS = now() - connectionCreatedEventTime;
135149
this.connectionId = connection.id;
136150
}
137151
}
@@ -194,14 +208,23 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent
194208
error?: MongoError;
195209
/** @internal */
196210
name = CONNECTION_CHECK_OUT_FAILED;
211+
/**
212+
* The time it took to check out the connection.
213+
* More specifically, the time elapsed between
214+
* emitting a `ConnectionCheckOutStartedEvent`
215+
* and emitting this event as part of the same check out.
216+
*/
217+
durationMS: number;
197218

198219
/** @internal */
199220
constructor(
200221
pool: ConnectionPool,
201222
reason: 'poolClosed' | 'timeout' | 'connectionError',
223+
checkoutTime: number,
202224
error?: MongoError
203225
) {
204226
super(pool);
227+
this.durationMS = now() - checkoutTime;
205228
this.reason = reason;
206229
this.error = error;
207230
}
@@ -217,10 +240,19 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent {
217240
connectionId: number | '<monitor>';
218241
/** @internal */
219242
name = CONNECTION_CHECKED_OUT;
243+
/**
244+
* The time it took to check out the connection.
245+
* More specifically, the time elapsed between
246+
* emitting a `ConnectionCheckOutStartedEvent`
247+
* and emitting this event as part of the same checking out.
248+
*
249+
*/
250+
durationMS: number;
220251

221252
/** @internal */
222-
constructor(pool: ConnectionPool, connection: Connection) {
253+
constructor(pool: ConnectionPool, connection: Connection, checkoutTime: number) {
223254
super(pool);
255+
this.durationMS = now() - checkoutTime;
224256
this.connectionId = connection.id;
225257
}
226258
}

‎src/mongo_logger.ts‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -604,6 +604,7 @@ export function defaultLogTransform(
604604
log = attachConnectionFields(log, logObject);
605605
log.message = 'Connection ready';
606606
log.driverConnectionId = logObject.connectionId;
607+
log.durationMS = logObject.durationMS;
607608
return log;
608609
case CONNECTION_CLOSED:
609610
log = attachConnectionFields(log, logObject);
@@ -653,11 +654,13 @@ export function defaultLogTransform(
653654
default:
654655
log.reason = `Unknown close reason: ${logObject.reason}`;
655656
}
657+
log.durationMS = logObject.durationMS;
656658
return log;
657659
case CONNECTION_CHECKED_OUT:
658660
log = attachConnectionFields(log, logObject);
659661
log.message = 'Connection checked out';
660662
log.driverConnectionId = logObject.connectionId;
663+
log.durationMS = logObject.durationMS;
661664
return log;
662665
case CONNECTION_CHECKED_IN:
663666
log = attachConnectionFields(log, logObject);

‎test/integration/connection-monitoring-and-pooling/unified-cmap-node-specs/connection-logging.json‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -191,6 +191,13 @@
191191
"long"
192192
]
193193
},
194+
"durationMS": {
195+
"$$type": [
196+
"double",
197+
"int",
198+
"long"
199+
]
200+
},
194201
"reason": "An error occurred while trying to establish a new connection",
195202
"error": {
196203
"$$exists": true

‎test/integration/retryable-writes/retryable_writes.spec.test.ts‎

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -63,7 +63,6 @@ describe('Legacy Retryable Writes Specs', function () {
6363
await ctx.client.close();
6464
ctx = {}; // reset context
6565
});
66-
6766
for (const spec of suite.tests) {
6867
// Step 2: Run the test
6968
const mochaTest = it(spec.description, async () => await executeScenarioTest(spec, ctx));

‎test/spec/connection-monitoring-and-pooling/logging/connection-logging.json‎

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -140,6 +140,13 @@
140140
"int",
141141
"long"
142142
]
143+
},
144+
"durationMS": {
145+
"$$type": [
146+
"double",
147+
"int",
148+
"long"
149+
]
143150
}
144151
}
145152
},
@@ -162,6 +169,13 @@
162169
"int",
163170
"long"
164171
]
172+
},
173+
"durationMS": {
174+
"$$type": [
175+
"double",
176+
"int",
177+
"long"
178+
]
165179
}
166180
}
167181
},
@@ -222,6 +236,13 @@
222236
"int",
223237
"long"
224238
]
239+
},
240+
"durationMS": {
241+
"$$type": [
242+
"double",
243+
"int",
244+
"long"
245+
]
225246
}
226247
}
227248
},
@@ -484,6 +505,13 @@
484505
"reason": "An error occurred while trying to establish a new connection",
485506
"error": {
486507
"$$exists": true
508+
},
509+
"durationMS": {
510+
"$$type": [
511+
"double",
512+
"int",
513+
"long"
514+
]
487515
}
488516
}
489517
}

‎test/spec/connection-monitoring-and-pooling/logging/connection-logging.yml‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -66,6 +66,7 @@ tests:
6666
driverConnectionId: { $$type: [int, long] }
6767
serverHost: { $$type: string }
6868
serverPort: { $$type: [int, long] }
69+
durationMS: { $$type: [double, int, long] }
6970

7071
- level: debug
7172
component: connection
@@ -74,6 +75,7 @@ tests:
7475
driverConnectionId: { $$type: [int, long] }
7576
serverHost: { $$type: string }
7677
serverPort: { $$type: [int, long] }
78+
durationMS: { $$type: [double, int, long] }
7779

7880
- level: debug
7981
component: connection
@@ -98,6 +100,7 @@ tests:
98100
driverConnectionId: { $$type: [int, long] }
99101
serverHost: { $$type: string }
100102
serverPort: { $$type: [int, long] }
103+
durationMS: { $$type: [double, int, long] }
101104

102105
- level: debug
103106
component: connection
@@ -218,3 +221,4 @@ tests:
218221
serverPort: { $$type: [int, long] }
219222
reason: "An error occurred while trying to establish a new connection"
220223
error: { $$exists: true }
224+
durationMS: { $$type: [double, int, long] }

‎test/spec/connection-monitoring-and-pooling/logging/connection-pool-options.json‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -128,6 +128,13 @@
128128
"int",
129129
"long"
130130
]
131+
},
132+
"durationMS": {
133+
"$$type": [
134+
"double",
135+
"int",
136+
"long"
137+
]
131138
}
132139
}
133140
}

‎test/spec/connection-monitoring-and-pooling/logging/connection-pool-options.yml‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -71,6 +71,7 @@ tests:
7171
driverConnectionId: { $$type: [int, long] }
7272
serverHost: { $$type: string }
7373
serverPort: { $$type: [int, long] }
74+
durationMS: { $$type: [double, int, long] }
7475

7576
# Drivers who have not done DRIVERS-1943 will need to skip this test.
7677
- description: "maxConnecting should be included in connection pool created message when specified"

0 commit comments

Comments
 (0)