Driver version matrix in CI; virtual clock for timing tests

.github/workflows/ci.yml

@@ -121,6 +121,71 @@ jobs:
         path: dist
     - run: npm run test:browser
 
+  # Old and new majors of every instrumented driver against real servers:
+  # a driver release that moves a patched method fails here, not silently.
+  driver-compat:
+    needs: build
+    runs-on: ubuntu-latest
+    timeout-minutes: 15
+    services:
+      postgres:
+        image: postgres:16
+        env:
+          POSTGRES_HOST_AUTH_METHOD: trust
+          POSTGRES_USER: traceperf
+        ports: ['5432:5432']
+        options: --health-cmd "pg_isready -U traceperf" --health-interval 2s --health-timeout 5s --health-retries 20
+      mysql:
+        image: mysql:8.4
+        env:
+          MYSQL_ALLOW_EMPTY_PASSWORD: 'yes'
+          MYSQL_DATABASE: traceperf
+        ports: ['3306:3306']
+        options: >-
+          --health-cmd "mysqladmin ping -h 127.0.0.1"
+          --health-interval 5s --health-timeout 5s --health-retries 30
+      mongo:
+        image: mongo:7.0
+        ports: ['27017:27017']
+        options: >-
+          --health-cmd "mongosh --quiet --eval 'db.runCommand({ ping: 1 }).ok'"
+          --health-interval 5s --health-timeout 5s --health-retries 20
+      # The legacy mysql driver cannot log in to MySQL 8 (caching_sha2_password);
+      # it is used with MariaDB / MySQL 5.7, so test it there
+      mariadb:
+        image: mariadb:11
+        env:
+          MARIADB_ALLOW_EMPTY_ROOT_PASSWORD: '1'
+          MARIADB_DATABASE: traceperf
+        ports: ['3307:3306']
+        options: >-
+          --health-cmd "healthcheck.sh --connect --innodb_initialized"
+          --health-interval 5s --health-timeout 5s --health-retries 30
+      redis:
+        image: redis:7
+        ports: ['6379:6379']
+        options: --health-cmd "redis-cli ping" --health-interval 2s --health-timeout 5s --health-retries 20
+    env:
+      TRACEPERF_PG_URL: postgres://traceperf@127.0.0.1:5432/traceperf
+      TRACEPERF_MONGO_URL: mongodb://127.0.0.1:27017
+      TRACEPERF_MYSQL_URL: mysql://root@127.0.0.1:3306/traceperf
+      TRACEPERF_REDIS_URL: redis://127.0.0.1:6379
+      TRACEPERF_MARIADB_URL: mysql://root@127.0.0.1:3307/traceperf
+      TRACEPERF_COMPAT_STRICT: '1'
+    steps:
+    - uses: actions/checkout@v4
+    - uses: actions/setup-node@v4
+      with:
+        node-version: 22.x
+    - uses: actions/download-artifact@v4
+      with:
+        name: dist
+        path: dist
+    - run: npm ci
+      working-directory: test/compat
+    - run: node compat.js
+      working-directory: test/compat
+
   # Bun and Deno run the ESM build (nesting, stats, exporters, browser entry).
   other-runtimes:
     needs: build
@@ -148,7 +213,7 @@ jobs:
       run: test/runtimes/workerd.sh
 
   publish-npm:
-    needs: [build, test, runtime, browser, other-runtimes]
+    needs: [build, test, runtime, browser, driver-compat, other-runtimes]
     if: github.event_name == 'push' && startsWith(github.ref, 'refs/tags/v')
     runs-on: ubuntu-latest
     permissions:

CHANGELOG.md

@@ -7,6 +7,13 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+### Fixed
+- **MongoDB driver 3.x / Mongoose 5:** `aggregate()` was labelled `mongo find $cmd`; it is now `mongo aggregate users`.
+
+### Changed
+- CI runs every driver integration against old and new majors on real servers (pg 8.0 and 8.x, mysql2 2 and 3, mysql 2, mongodb 3–7, Mongoose 5–8, ioredis 4 and 5, better-sqlite3 11 and 12): `test/compat`. The first run found the bug above.
+- Timing tests that assert on synchronous durations use a virtual clock, so a loaded CI machine can't fail them.
+
 ## [1.8.0] - 2026-11-06
 
 ### Added

src/__tests__/browser-tracking.test.ts

@@ -3,7 +3,7 @@
  * README: createTracePerf({...}).track / createTrackable.
  */
 import { createTracePerf, BrowserLogger, TrackingMode } from '../browser';
-import { busyWait, captureLogs } from './helpers/console';
+import { busyWait, captureLogs, withVirtualClock } from './helpers/console';
 
 describe('browser tracking', () => {
   let logs: ReturnType<typeof captureLogs>;
@@ -74,15 +74,15 @@ describe('browser tracking', () => {
     expect(logs.lines()).toEqual([]);
   });
 
-  test('threshold hides fast calls', () => {
+  test('threshold hides fast calls', withVirtualClock(() => {
     const tracker = createTracePerf({ threshold: 60 });
     tracker.track(() => 1, { label: 'fastOperation' });
     tracker.track(() => busyWait(70), { label: 'slowOperation' });
     createTracePerf().track(() => 1, { label: 'perCallFast', threshold: 60 });
     expect(logs.text()).not.toContain('fastOperation');
     expect(logs.text()).not.toContain('perCallFast');
     expect(logs.text()).toContain('slowOperation');
-  });
+  }));
 
   test('createTracePerf({ logger }) uses the given BrowserLogger', () => {
     const logger = new BrowserLogger({ silent: true });

src/__tests__/features.test.ts

@@ -13,7 +13,7 @@ import {
   StatsCollector,
   OtelApiLike,
 } from '../index';
-import { busyWait, captureLogs } from './helpers/console';
+import { busyWait, captureLogs, withVirtualClock } from './helpers/console';
 
 const sleep = (ms: number) => new Promise(r => setTimeout(r, ms));
 
@@ -159,7 +159,7 @@ describe('statistics', () => {
     });
   });
 
-  test('tracked calls feed stats: counts and errors are exact', () => {
+  test('tracked calls feed stats: counts and errors are exact', withVirtualClock(() => {
     const tp = createTracePerf({ silent: true });
     const f = tp.createTrackable((ms: number) => { busyWait(ms); if (ms > 20) throw new Error('slow'); }, { label: 'work' });
     for (const ms of [0, 0, 0, 0, 30]) {
@@ -168,11 +168,11 @@ describe('statistics', () => {
     const s = tp.getStats('work')!;
     expect(s.count).toBe(5);
     expect(s.errors).toBe(1);
-    expect(s.max).toBeGreaterThanOrEqual(29);
+    expect(s.max).toBeCloseTo(30, 6);
     expect(s.p50).toBeLessThan(s.max);
     expect(s.min).toBeLessThanOrEqual(s.p50);
     expect(s.mean).toBeCloseTo(s.total / 5, 6);
-  });
+  }));
 
   test('memory stays bounded with many calls and many labels', () => {
     const tp = createTracePerf({ silent: true, trackMemory: false, stats: { reservoirSize: 16, maxLabels: 10 } });
@@ -424,7 +424,7 @@ describe('event loop monitor', () => {
 });
 
 describe('onSlow', () => {
-  test('fires for slow calls at any depth with a single threshold', () => {
+  test('fires for slow calls at any depth with a single threshold', withVirtualClock(() => {
     const tp = createTracePerf({ silent: true, trackMemory: false });
     const hits: string[] = [];
     const off = tp.onSlow(15, (call, root) => hits.push(`${call.label}@${root.label}`));
@@ -434,9 +434,9 @@ describe('onSlow', () => {
     off();
     tp.track(() => busyWait(20), { label: 'afterOff' });
     expect(hits).toEqual(['root@root', 'slowChild@root']);
-  });
+  }));
 
-  test('per-label thresholds with a * default', () => {
+  test('per-label thresholds with a * default', withVirtualClock(() => {
     const tp = createTracePerf({ silent: true, trackMemory: false, trackingMode: TrackingMode.PERFORMANCE });
     const hits: string[] = [];
     tp.onSlow({ 'db.query': 5, '*': 1000 }, call => hits.push(call.label));
@@ -447,5 +447,5 @@ describe('onSlow', () => {
     tp.onSlow({ only: 1 }, call => none.push(call.label));
     tp.track(() => busyWait(5), { label: 'unlisted' });
     expect(none).toEqual([]);
-  });
+  }));
 });

src/__tests__/helpers/console.ts

@@ -13,9 +13,45 @@ export function captureLogs(): { lines: () => string[]; text: () => string; rest
   };
 }
 
+let virtualNow: number | undefined;
+
+/**
+ * Replace performance.now() with a clock that only moves when busyWait()
+ * runs, so sync timing assertions are exact and immune to machine load.
+ * Returns a restore function. Not for code that awaits real timers.
+ */
+export function useVirtualClock(): () => void {
+  // An own property shadows Performance.prototype.now (read-only for assignment on Node 18)
+  const hadOwn = Object.prototype.hasOwnProperty.call(performance, 'now');
+  const previous = Object.getOwnPropertyDescriptor(performance, 'now');
+  Object.defineProperty(performance, 'now', { value: () => virtualNow as number, configurable: true, writable: true });
+  virtualNow = 1000;
+  return () => {
+    virtualNow = undefined;
+    if (hadOwn && previous) Object.defineProperty(performance, 'now', previous);
+    else delete (performance as { now?: unknown }).now;
+  };
+}
+
 export function busyWait(ms: number): void {
+  if (virtualNow !== undefined) {
+    virtualNow += ms;
+    return;
+  }
   const start = Date.now();
   while (Date.now() - start < ms) {
     // spin
   }
 }
+
+/** Run a synchronous test body on the virtual clock (see useVirtualClock). */
+export function withVirtualClock(body: () => void): () => void {
+  return () => {
+    const restore = useVirtualClock();
+    try {
+      body();
+    } finally {
+      restore();
+    }
+  };
+}

src/__tests__/prometheus.test.ts

@@ -1,7 +1,7 @@
 import * as http from 'http';
 import { AddressInfo } from 'net';
 import { createTracePerf, prometheusExporter } from '../index';
-import { busyWait } from './helpers/console';
+import { busyWait, useVirtualClock } from './helpers/console';
 
 /** Minimal exposition-format parser: { 'metric{labels}': value } */
 function parse(text: string): Record<string, number> {
@@ -16,21 +16,25 @@ function parse(text: string): Record<string, number> {
 }
 
 test('histogram buckets, sum, count and errors per label', () => {
+  const restore = useVirtualClock();
+  try {
   const prom = prometheusExporter({ buckets: [0.02, 0.2] });
   const tp = createTracePerf({ silent: true, trackMemory: false, plugins: [prom] });
   const query = tp.createTrackable((ms: number) => busyWait(ms), { label: 'db.query' });
-  // A call doing nothing must land in the first bucket even on a busy machine (wide margin)
   tp.track(() => { query(0); query(40); }, { label: 'GET /x' });
   expect(() => tp.track(() => { throw new Error('x'); }, { label: 'job "a"\nb' })).toThrow();
   const m = parse(prom.metrics());
   expect(m['traceperf_call_duration_seconds_bucket{name="db.query",le="0.02"}']).toBe(1);
   expect(m['traceperf_call_duration_seconds_bucket{name="db.query",le="0.2"}']).toBe(2);
   expect(m['traceperf_call_duration_seconds_bucket{name="db.query",le="+Inf"}']).toBe(2);
   expect(m['traceperf_call_duration_seconds_count{name="db.query"}']).toBe(2);
-  expect(m['traceperf_call_duration_seconds_sum{name="db.query"}']).toBeGreaterThanOrEqual(0.039);
+  expect(m['traceperf_call_duration_seconds_sum{name="db.query"}']).toBeCloseTo(0.04, 6);
   expect(m['traceperf_call_duration_seconds_count{name="GET /x"}']).toBe(1);
   expect(m['traceperf_call_errors_total{name="job \\"a\\"\\nb"}']).toBe(1);
   expect(prom.metrics()).toMatch(/# TYPE traceperf_call_duration_seconds histogram/);
+  } finally {
+    restore();
+  }
 });
 
 test('rootsOnly, label cap, reset, invalid prefix', () => {

src/__tests__/tracking-threshold.test.ts

@@ -2,26 +2,25 @@
  * Regression: `threshold` (milliseconds) must filter what gets reported.
  */
 import { createTracePerf } from '../index';
-import { busyWait, captureLogs } from './helpers/console';
+import { busyWait, captureLogs, withVirtualClock } from './helpers/console';
 
 describe('threshold', () => {
   let logs: ReturnType<typeof captureLogs>;
   beforeEach(() => { logs = captureLogs(); });
   afterEach(() => logs.restore());
 
-  test('instance threshold hides fast calls and reports slow ones', () => {
-    // Wide margins: a no-op vs. a 60ms threshold, so CPU contention can't flip it
+  test('instance threshold hides fast calls and reports slow ones', withVirtualClock(() => {
     const tp = createTracePerf({ threshold: 60 });
     tp.track(() => 1, { label: 'fast' });
     tp.track(() => busyWait(70), { label: 'slow' });
     expect(logs.text()).not.toContain('fast');
     expect(logs.text()).toContain('slow');
-  });
+  }));
 
-  test('per-call threshold hides fast calls', () => {
+  test('per-call threshold hides fast calls', withVirtualClock(() => {
     createTracePerf().track(() => 1, { label: 'fastPerCall', threshold: 60 });
     expect(logs.lines()).toEqual([]);
-  });
+  }));
 
   test('threshold applies to async functions using their full duration', async () => {
     const tp = createTracePerf({ threshold: 30 });

src/drivers.ts

@@ -207,6 +207,9 @@ export function instrumentMongo(tp: OptimizedPerformanceMonitor, mongodb: any, o
     }, restores);
   }
   const cursorName = (cursor: any): string => {
+    // Driver 3.x aggregation cursors run on "db.$cmd"; the collection is the operation's target
+    const target = cursor && cursor.operation && cursor.operation.target;
+    if (typeof target === 'string') return target;
     const ns = cursor && cursor.namespace;
     if (ns && (ns.collection || ns.coll)) return ns.collection || ns.coll;
     // Driver 3.x: "db.collection"
@@ -218,7 +221,10 @@ export function instrumentMongo(tp: OptimizedPerformanceMonitor, mongodb: any, o
     const proto = mongodb && mongodb[className] && mongodb[className].prototype;
     patchMethod(proto, 'toArray', original => function (this: any, ...args: unknown[]) {
       const cb = typeof args[args.length - 1] === 'function' ? args.length - 1 : -1;
-      return trackCall(tp, `mongo ${op} ${cursorName(this)}`, options, this, original, args, cb);
+      // Driver 3.x: AggregationCursor inherits Cursor's toArray, so ask the instance
+      const Aggregation = mongodb.AggregationCursor;
+      const kind = typeof Aggregation === 'function' && this instanceof Aggregation ? 'aggregate' : op;
+      return trackCall(tp, `mongo ${kind} ${cursorName(this)}`, options, this, original, args, cb);
     }, restores);
   }
   return () => restores.forEach(r => r());