fix(NODE-7307): Replace node:process.hrtime() with performance.now() (#4816)

Author: PavelSafronov

etc/sdam_viz.js

@@ -5,7 +5,7 @@
 // npx ts-node etc/sdam_viz.js -h
 
 const { MongoClient } = require('../src');
-const { now, calculateDurationInMs, arrayStrictEqual, errorStrictEqual } = require('../src/utils');
+const { calculateDurationInMs, arrayStrictEqual, errorStrictEqual, processTimeMS } = require('../src/utils');
 
 const util = require('util');
 const chalk = require('chalk');
@@ -207,7 +207,7 @@ async function scheduleWriteWorkload(client) {
   const currentWriteWorkload = writeWorkloadCounter++;
 
   try {
-    const start = now();
+    const start = processTimeMS();
     await client.db('test').collection('test').insertOne({ a: 42 });
     averageWriteMS = 0.2 * calculateDurationInMs(start) + 0.8 * averageWriteMS;
 

src/cmap/connection.ts

@@ -47,8 +47,8 @@ import {
   maxWireVersion,
   type MongoDBNamespace,
   noop,
-  now,
   once,
+  processTimeMS,
   squashError,
   uuidV4
 } from '../utils';
@@ -241,7 +241,7 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
 
     this.description = new StreamDescription(this.address, options);
     this.generation = options.generation;
-    this.lastUseTime = now();
+    this.lastUseTime = processTimeMS();
 
     this.messageStream = this.socket
       .on('error', this.onSocketError.bind(this))
@@ -299,7 +299,7 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
   }
 
   public markAvailable(): void {
-    this.lastUseTime = now();
+    this.lastUseTime = processTimeMS();
   }
 
   private onSocketError(cause: Error) {
@@ -510,7 +510,7 @@ export class Connection extends TypedEventEmitter<ConnectionEvents> {
     const message = this.prepareCommand(ns.db, command, options);
     let started = 0;
     if (this.shouldEmitAndLogCommand) {
-      started = now();
+      started = processTimeMS();
       this.emitAndLogCommand(
         this.monitorCommands,
         Connection.COMMAND_STARTED,

src/cmap/connection_pool.ts

@@ -36,7 +36,7 @@ import {
   List,
   makeCounter,
   noop,
-  now,
+  processTimeMS,
   promiseWithResolvers
 } from '../utils';
 import { connect } from './connect';
@@ -319,7 +319,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
    * explicitly destroyed by the new owner.
    */
   async checkOut(options: { timeoutContext: TimeoutContext } & Abortable): Promise<Connection> {
-    const checkoutTime = now();
+    const checkoutTime = processTimeMS();
     this.emitAndLog(
       ConnectionPool.CONNECTION_CHECK_OUT_STARTED,
       new ConnectionCheckOutStartedEvent(this)
@@ -616,7 +616,7 @@ export class ConnectionPool extends TypedEventEmitter<ConnectionPoolEvents> {
 
     this.pending++;
     // This is our version of a "virtual" no-I/O connection as the spec requires
-    const connectionCreatedTime = now();
+    const connectionCreatedTime = processTimeMS();
     this.emitAndLog(
       ConnectionPool.CONNECTION_CREATED,
       new ConnectionCreatedEvent(this, { id: connectOptions.id })

src/cmap/connection_pool_events.ts

@@ -13,7 +13,7 @@ import {
   CONNECTION_READY
 } from '../constants';
 import type { MongoError } from '../error';
-import { now } from '../utils';
+import { processTimeMS } from '../utils';
 import type { Connection } from './connection';
 import type { ConnectionPool, ConnectionPoolOptions } from './connection_pool';
 
@@ -145,7 +145,7 @@ export class ConnectionReadyEvent extends ConnectionPoolMonitoringEvent {
   /** @internal */
   constructor(pool: ConnectionPool, connection: Connection, connectionCreatedEventTime: number) {
     super(pool);
-    this.durationMS = now() - connectionCreatedEventTime;
+    this.durationMS = processTimeMS() - connectionCreatedEventTime;
     this.connectionId = connection.id;
   }
 }
@@ -224,7 +224,7 @@ export class ConnectionCheckOutFailedEvent extends ConnectionPoolMonitoringEvent
     error?: MongoError
   ) {
     super(pool);
-    this.durationMS = now() - checkoutTime;
+    this.durationMS = processTimeMS() - checkoutTime;
     this.reason = reason;
     this.error = error;
   }
@@ -252,7 +252,7 @@ export class ConnectionCheckedOutEvent extends ConnectionPoolMonitoringEvent {
   /** @internal */
   constructor(pool: ConnectionPool, connection: Connection, checkoutTime: number) {
     super(pool);
-    this.durationMS = now() - checkoutTime;
+    this.durationMS = processTimeMS() - checkoutTime;
     this.connectionId = connection.id;
   }
 }

src/sdam/monitor.ts

@@ -14,8 +14,8 @@ import {
   type EventEmitterWithState,
   makeStateMachine,
   noop,
-  now,
-  ns
+  ns,
+  processTimeMS
 } from '../utils';
 import { ServerType, STATE_CLOSED, STATE_CLOSING } from './common';
 import {
@@ -326,7 +326,7 @@ function checkServer(monitor: Monitor, callback: Callback<Document | null>) {
       );
       // We have not actually sent an outgoing handshake, but when we get the next response we
       // want the duration to reflect the time since we last heard from the server
-      start = now();
+      start = processTimeMS();
     } else {
       monitor.rttPinger?.close();
       monitor.rttPinger = undefined;
@@ -360,7 +360,7 @@ function checkServer(monitor: Monitor, callback: Callback<Document | null>) {
     }
 
     // Record new start time before sending handshake
-    start = now();
+    start = processTimeMS();
 
     if (isAwaitable) {
       awaited = true;
@@ -383,7 +383,7 @@ function checkServer(monitor: Monitor, callback: Callback<Document | null>) {
     const socket = await makeSocket(monitor.connectOptions);
     const connection = makeConnection(monitor.connectOptions, socket);
     // The start time is after socket creation but before the handshake
-    start = now();
+    start = processTimeMS();
     try {
       await performInitialHandshake(connection, monitor.connectOptions);
       return connection;
@@ -532,7 +532,7 @@ export class RTTPinger {
   }
 
   private measureRoundTripTime() {
-    const start = now();
+    const start = processTimeMS();
 
     if (this.closed) {
       return;
@@ -607,7 +607,7 @@ export class MonitorInterval {
   }
 
   wake() {
-    const currentTime = now();
+    const currentTime = processTimeMS();
     const timeSinceLastCall = currentTime - this.lastExecutionEnded;
 
     // TODO(NODE-4674): Add error handling and logging to the monitor
@@ -651,7 +651,7 @@ export class MonitorInterval {
   }
 
   toJSON() {
-    const currentTime = now();
+    const currentTime = processTimeMS();
     const timeSinceLastCall = currentTime - this.lastExecutionEnded;
     return {
       timerId: this.timerId != null ? 'set' : 'cleared',
@@ -684,7 +684,7 @@ export class MonitorInterval {
     this.isExecutionInProgress = true;
 
     this.fn(() => {
-      this.lastExecutionEnded = now();
+      this.lastExecutionEnded = processTimeMS();
       this.isExecutionInProgress = false;
       this._reschedule(this.heartbeatFrequencyMS);
     });

src/sdam/server_description.ts

@@ -1,6 +1,12 @@
 import { type Document, Long, type ObjectId } from '../bson';
 import { type MongoError, MongoRuntimeError } from '../error';
-import { arrayStrictEqual, compareObjectId, errorStrictEqual, HostAddress, now } from '../utils';
+import {
+  arrayStrictEqual,
+  compareObjectId,
+  errorStrictEqual,
+  HostAddress,
+  processTimeMS
+} from '../utils';
 import { type ClusterTime, ServerType } from './common';
 
 const WRITABLE_SERVER_TYPES = new Set<ServerType>([
@@ -110,7 +116,7 @@ export class ServerDescription {
     this.maxWireVersion = hello?.maxWireVersion ?? 0;
     this.roundTripTime = options?.roundTripTime ?? -1;
     this.minRoundTripTime = options?.minRoundTripTime ?? 0;
-    this.lastUpdateTime = now();
+    this.lastUpdateTime = processTimeMS();
     this.lastWriteDate = hello?.lastWrite?.lastWriteDate ?? 0;
     // NOTE: This actually builds the stack string instead of holding onto the getter and all its
     // associated references. This is done to prevent a memory leak.

src/sdam/topology.ts

@@ -45,7 +45,7 @@ import {
   List,
   makeStateMachine,
   noop,
-  now,
+  processTimeMS,
   promiseWithResolvers,
   shuffle
 } from '../utils';
@@ -602,7 +602,7 @@ export class Topology extends TypedEventEmitter<TopologyEvents> {
       resolve,
       reject,
       cancelled: false,
-      startTime: now(),
+      startTime: processTimeMS(),
       operationName: options.operationName,
       waitingLogged: false,
       previousServer: options.previousServer
@@ -1001,7 +1001,8 @@ function processWaitQueue(topology: Topology) {
               waitQueueMember.serverSelector,
               topology.description,
               topology.s.serverSelectionTimeoutMS !== 0
-                ? topology.s.serverSelectionTimeoutMS - (now() - waitQueueMember.startTime)
+                ? topology.s.serverSelectionTimeoutMS -
+                  (processTimeMS() - waitQueueMember.startTime)
                 : -1,
               waitQueueMember.operationName
             )

src/sessions.ts

@@ -42,7 +42,7 @@ import {
   List,
   MongoDBNamespace,
   noop,
-  now,
+  processTimeMS,
   squashError,
   uuidV4
 } from './utils';
@@ -726,7 +726,9 @@ export class ClientSession
           })
         : null;
 
-    const startTime = this.timeoutContext?.csotEnabled() ? this.timeoutContext.start : now();
+    const startTime = this.timeoutContext?.csotEnabled()
+      ? this.timeoutContext.start
+      : processTimeMS();
 
     let committed = false;
     let result: any;
@@ -768,7 +770,7 @@ export class ClientSession
 
           if (
             fnError.hasErrorLabel(MongoErrorLabel.TransientTransactionError) &&
-            (this.timeoutContext != null || now() - startTime < MAX_TIMEOUT)
+            (this.timeoutContext != null || processTimeMS() - startTime < MAX_TIMEOUT)
           ) {
             continue;
           }
@@ -796,14 +798,14 @@ export class ClientSession
             if (
               !isMaxTimeMSExpiredError(commitError) &&
               commitError.hasErrorLabel(MongoErrorLabel.UnknownTransactionCommitResult) &&
-              (this.timeoutContext != null || now() - startTime < MAX_TIMEOUT)
+              (this.timeoutContext != null || processTimeMS() - startTime < MAX_TIMEOUT)
             ) {
               continue;
             }
 
             if (
               commitError.hasErrorLabel(MongoErrorLabel.TransientTransactionError) &&
-              (this.timeoutContext != null || now() - startTime < MAX_TIMEOUT)
+              (this.timeoutContext != null || processTimeMS() - startTime < MAX_TIMEOUT)
             ) {
               break;
             }
@@ -943,7 +945,7 @@ export class ServerSession {
       return;
     }
     this.id = { id: new Binary(uuidV4(), Binary.SUBTYPE_UUID) };
-    this.lastUse = now();
+    this.lastUse = processTimeMS();
     this.txnNumber = 0;
     this.isDirty = false;
   }
@@ -1078,7 +1080,7 @@ export function applySession(
   }
 
   // mark the last use of this session, and apply the `lsid`
-  serverSession.lastUse = now();
+  serverSession.lastUse = processTimeMS();
   command.lsid = serverSession.id;
 
   const inTxnOrTxnCommand = session.inTransaction() || isTransactionCommand(command);

src/utils.ts

@@ -434,10 +434,13 @@ export function makeStateMachine(stateTable: StateTable): StateTransitionFunctio
   };
 }
 
-/** @internal */
-export function now(): number {
-  const hrtime = process.hrtime();
-  return Math.floor(hrtime[0] * 1000 + hrtime[1] / 1000000);
+/**
+ * This function returns the number of milliseconds since an arbitrary point in time.
+ * This function should only be used to measure time intervals.
+ * @internal
+ * */
+export function processTimeMS(): number {
+  return Math.floor(performance.now());
 }
 
 /** @internal */
@@ -446,7 +449,7 @@ export function calculateDurationInMs(started: number | undefined): number {
     return -1;
   }
 
-  const elapsed = now() - started;
+  const elapsed = processTimeMS() - started;
   return elapsed < 0 ? 0 : elapsed;
 }