From 1a59266fad4c3dfcb9610e18b1877c2f0527bebe Mon Sep 17 00:00:00 2001 From: Ibrahim Roshdy <22573766+ibrahimroshdy@users.noreply.github.com> Date: Sat, 17 Oct 2026 18:33:41 +0300 Subject: [PATCH] test(perf): scale the nightly limits by how fast the runner is (#159) The nightly perf job failed on slower GitHub runners with unchanged code. The run now times a fixed reference workload first: pure JS, plain SQL and an exact vector scan, none of it Kept's code. Every millisecond limit in test/perf is multiplied by the speed factor, clamped to [1, 3]. The reports and failure messages print the factor and the scaled limit. A regression still fails, because the reference work doesn't slow down with the code. The reference values are inferred from a local M1 Pro run and the snapshot bench's M1 Pro-to- EPYC 9V45 ratio. Re-pin them from a fast night's calibration.json. Closes #159 Signed-off-by: Ibrahim Roshdy <22573766+ibrahimroshdy@users.noreply.github.com> --- .github/workflows/perf.yml | 4 +- apps/server/test/perf-calibration.test.ts | 107 ++++++++++++ apps/server/test/perf/calibrate.ts | 175 ++++++++++++++++++++ apps/server/test/perf/calibration.ts | 111 +++++++++++++ apps/server/test/perf/global-setup.ts | 31 ++++ apps/server/test/perf/limits.ts | 25 +++ apps/server/test/perf/step3.perf.test.ts | 13 +- apps/server/test/perf/step4.perf.test.ts | 17 +- apps/server/test/perf/steps6-8.perf.test.ts | 17 +- apps/server/test/perf/vehicles.perf.test.ts | 24 ++- apps/server/vitest.perf.config.ts | 4 +- scripts/ci-local.sh | 1 + 12 files changed, 503 insertions(+), 26 deletions(-) create mode 100644 apps/server/test/perf-calibration.test.ts create mode 100644 apps/server/test/perf/calibrate.ts create mode 100644 apps/server/test/perf/calibration.ts create mode 100644 apps/server/test/perf/global-setup.ts create mode 100644 apps/server/test/perf/limits.ts diff --git a/.github/workflows/perf.yml b/.github/workflows/perf.yml index 5e0a68b4..0a5e6180 100644 --- a/.github/workflows/perf.yml +++ b/.github/workflows/perf.yml @@ -2,7 +2,9 @@ # by hand. It is a report, not a gate: timing limits measured on a shared runner are noisy, so a # slow night never blocks a pull request or a release (they failed the laptop gate on load alone, # 2026-10-08). A failed run shows on the Actions page; its numbers are kept as an artifact for a -# month, so a trend can be read. Gated on a public repository, like ci.yml. +# month, so a trend can be read. The test/perf limits are multiplied by the runner's speed, timed +# on a fixed reference workload at the start of the run (apps/server/test/perf/calibration.ts, +# #159): runners of different speeds land here. Gated on a public repository, like ci.yml. # # Actions pinned by commit SHA with their tag in a comment (spike W1). name: perf diff --git a/apps/server/test/perf-calibration.test.ts b/apps/server/test/perf-calibration.test.ts new file mode 100644 index 00000000..2619cb69 --- /dev/null +++ b/apps/server/test/perf-calibration.test.ts @@ -0,0 +1,107 @@ +import { describe, expect, it } from 'vitest'; +import { CPU_CHECKSUM, cpuWork } from './perf/calibrate.js'; +import { + type ComponentMs, + calibrationOf, + judge, + MAX_FACTOR, + REFERENCE_MS, + scaledLimit, +} from './perf/calibration.js'; + +// The perf run's speed factor and scaled limits (test/perf/calibration.ts, issue #159), without +// the perf run: the arithmetic, and that a real regression still fails on any runner. + +const REF: ComponentMs = { cpu: 200, db: 400, vector: 300 }; +const times = (k: ComponentMs | number, ref = REF): ComponentMs => + typeof k === 'number' + ? { cpu: ref.cpu * k, db: ref.db * k, vector: ref.vector * k } + : { cpu: ref.cpu * k.cpu, db: ref.db * k.db, vector: ref.vector * k.vector }; + +// The nightly figures the issue is about (semantic search's p95 under §3.1's 300 ms): the fast +// runner on Oct 12 and a slow one on Oct 17, the same code. On the slow night the snapshot bench, +// which no limit here scales, ran its full snapshot at p50 523.6 ms against 311.5 ms: 1.68×. That +// stands in for the slow runner's reference work. +const SEARCH_LIMIT_MS = 300; +const FAST_NIGHT_SEARCH_P95 = 159.3; +const SLOW_NIGHT_SEARCH_P95 = 402.7; +const SLOW_RUNNER = 1.68; + +describe('the runner speed factor', () => { + it('is 1 on the reference runner', () => { + const c = calibrationOf(REF, REF); + expect(c.raw).toBe(1); + expect(c.factor).toBe(1); + expect(c.ratios).toEqual({ cpu: 1, db: 1, vector: 1 }); + }); + + it('never goes below 1 on a faster runner', () => { + const c = calibrationOf(times(0.6), REF); + expect(c.raw).toBe(0.6); + expect(c.factor).toBe(1); + }); + + it('is the geometric mean of the parts on a slower one', () => { + expect(calibrationOf(times(1.6), REF).factor).toBe(1.6); + // Vector arithmetic slowed most on the slow nights: (1.5 × 1.5 × 2.5)^(1/3). + const c = calibrationOf(times({ cpu: 1.5, db: 1.5, vector: 2.5 }), REF); + expect(c.ratios).toEqual({ cpu: 1.5, db: 1.5, vector: 2.5 }); + expect(c.factor).toBe(1.78); + }); + + it(`stops at ${MAX_FACTOR}`, () => { + const c = calibrationOf(times(5), REF); + expect(c.raw).toBe(5); + expect(c.factor).toBe(MAX_FACTOR); + expect(scaledLimit(100, 5)).toBe(100 * MAX_FACTOR); + }); + + it('refuses a missing or non-positive timing', () => { + expect(() => calibrationOf({ ...REF, db: 0 }, REF)).toThrow(/measured db is 0/); + expect(() => calibrationOf({ ...REF, cpu: Number.NaN }, REF)).toThrow(/measured cpu/); + expect(() => calibrationOf(REF, { ...REF, vector: -1 })).toThrow(/reference vector/); + }); + + it('has a pinned reference for every part', () => { + expect(() => calibrationOf(REFERENCE_MS)).not.toThrow(); + }); + + it('runs the same workload everywhere (re-pin REFERENCE_MS when its checksum changes)', () => { + expect(cpuWork()).toBe(CPU_CHECKSUM); + }); +}); + +describe('a scaled limit', () => { + it('is the limit times the factor, to 0.1 ms', () => { + expect(scaledLimit(300, 1)).toBe(300); + expect(scaledLimit(110.4, 1.37)).toBe(151.2); + expect(scaledLimit(300, 0.5)).toBe(300); + }); + + it('names the factor and the scaled limit when it fails', () => { + const v = judge('searchSemanticP95Ms', 520, 300, 1.68); + expect(v).toMatchObject({ limitMs: 300, factor: 1.68, scaledLimitMs: 504, pass: false }); + expect(v.message).toBe( + 'searchSemanticP95Ms: 520 ms against 300 ms × 1.68 (runner speed) = 504 ms', + ); + }); +}); + +describe('a 2× regression still fails', () => { + it('on the reference runner (factor 1)', () => { + const factor = calibrationOf(REF, REF).factor; + expect(judge('search', FAST_NIGHT_SEARCH_P95, SEARCH_LIMIT_MS, factor).pass).toBe(true); + expect(judge('search', FAST_NIGHT_SEARCH_P95 * 2, SEARCH_LIMIT_MS, factor).pass).toBe(false); + }); + + it('on a slow runner, whose reference work does not slow down with the code', () => { + // The fixed limit failed the unchanged code on the slow night (the bug). + expect(judge('search', SLOW_NIGHT_SEARCH_P95, SEARCH_LIMIT_MS, 1).pass).toBe(false); + // Calibrated once per run: the regression is in search, so the reference work, and the + // factor, are the same with or without it. + const factor = calibrationOf(times(SLOW_RUNNER), REF).factor; + expect(factor).toBe(SLOW_RUNNER); + expect(judge('search', SLOW_NIGHT_SEARCH_P95, SEARCH_LIMIT_MS, factor).pass).toBe(true); + expect(judge('search', SLOW_NIGHT_SEARCH_P95 * 2, SEARCH_LIMIT_MS, factor).pass).toBe(false); + }); +}); diff --git a/apps/server/test/perf/calibrate.ts b/apps/server/test/perf/calibrate.ts new file mode 100644 index 00000000..d646fbd2 --- /dev/null +++ b/apps/server/test/perf/calibrate.ts @@ -0,0 +1,175 @@ +import os from 'node:os'; +import { performance } from 'node:perf_hooks'; +import pg from 'pg'; +import { CONNECTION_OPTIONS } from '../../src/db/pools.js'; +import { type Calibration, type ComponentMs, calibrationOf } from './calibration.js'; + +// The reference workload (issue #159): how fast this runner is, timed once at the start of the +// perf run (test/perf/global-setup.ts), before any check. Fixed and deterministic, and none of it +// Kept's code, so a regression in Kept never makes it slower: +// - cpu: pure JavaScript in this process: 150,000 records built, sent through JSON and back, +// sorted by a string key, grouped in a Map and normalised (what a request's handler does). +// - db: plain SQL in a scratch database, one statement at a time, all of the work inside +// Postgres: 100,000 rows into a temporary table, an index, a grouped aggregate, an ordered +// page deep in the index and a self-join. +// - vector: an exact cosine scan of 10,000 768-dimension vectors for the 50 nearest, ten times +// (the shape of semantic search, kept.semantic_thing_ids, at the perf fixture's size). On the +// slow nights semantic search slowed about 2.5× while most checks slowed 1.5–1.8×, so vector +// arithmetic gets its own part. +// Each part runs CALIBRATION_WARMUP + CALIBRATION_RUNS times; its fastest run counts (the least +// disturbed by anything else on the machine). Commits and round trips are left out on purpose: +// their cost depends on the disk and on Docker's networking (Docker Desktop's VM on a Mac), not on +// how fast the runner computes. +// +// About 5–10 s in all. + +export const CALIBRATION_WARMUP = 1; +export const CALIBRATION_RUNS = 5; +const CPU_RECORDS = 150_000; +const DB_ROWS = 100_000; +const VECTORS = 10_000; +const BASES = 100; +const DIMS = 768; +const VECTOR_QUERIES = 10; + +/** The checksum cpuWork() returns; another value means the workload changed (re-pin). */ +export const CPU_CHECKSUM = 99_834_549; + +/** The pure-JavaScript part. Returns a checksum so none of it can be optimised away. */ +export function cpuWork(): number { + type Row = { id: number; name: string; qty: number; tags: string[] }; + const rows: Row[] = []; + let seed = 1; + for (let i = 0; i < CPU_RECORDS; i++) { + seed = (seed * 1_103_515_245 + 12_345) % 2_147_483_648; + rows.push({ + id: i, + name: `Thing ${seed.toString(36)} Ünïcode`, + qty: seed % 97, + tags: [`t${seed % 13}`, `t${seed % 7}`], + }); + } + const back = JSON.parse(JSON.stringify(rows)) as Row[]; + back.sort((a, b) => (a.name < b.name ? -1 : a.name > b.name ? 1 : a.id - b.id)); + const groups = new Map(); + let sum = 0; + for (const [i, r] of back.entries()) { + for (const t of r.tags) groups.set(t, (groups.get(t) ?? 0) + r.qty); + const n = r.name.normalize('NFKD').toLowerCase(); + sum = (sum * 31 + n.length + i * r.qty) % 1_000_000_007; + } + for (const [k, v] of [...groups].sort()) sum = (sum * 31 + k.length * v) % 1_000_000_007; + return sum; +} + +async function fastest(fn: () => Promise): Promise { + let best = Number.POSITIVE_INFINITY; + for (let i = 0; i < CALIBRATION_WARMUP + CALIBRATION_RUNS; i++) { + const start = performance.now(); + await fn(); + const ms = performance.now() - start; + if (i >= CALIBRATION_WARMUP) best = Math.min(best, ms); + } + return Math.round(best * 10) / 10; +} + +async function dbWork(client: pg.Client): Promise { + await client.query( + `CREATE TEMP TABLE cal_rows AS + SELECT n AS id, md5(n::text) AS name, n % 97 AS qty, + jsonb_build_object('k', n % 13, 'v', md5((n * 7)::text)) AS doc + FROM generate_series(1, ${DB_ROWS}) AS n`, + ); + await client.query('CREATE INDEX ON cal_rows (name)'); + await client.query('ANALYZE cal_rows'); + await client.query( + `SELECT doc->>'k' AS k, count(*), sum(qty), max(name) FROM cal_rows GROUP BY 1 ORDER BY 1`, + ); + await client.query('SELECT id FROM cal_rows ORDER BY name DESC LIMIT 50 OFFSET 40000'); + await client.query( + `SELECT count(*) FROM cal_rows a JOIN cal_rows b ON b.id = a.id + 1 WHERE a.qty < b.qty`, + ); + await client.query('DROP TABLE cal_rows'); +} + +async function vectorSetup(client: pg.Client): Promise { + // Deterministic and distinct: 100 base vectors (a sine of the row and the dimension), and each + // of the 10,000 the sum of two of them. + await client.query( + `CREATE TEMP TABLE cal_base AS + SELECT b, (SELECT array_agg(sin(b * 0.37 + d * 0.11)::real ORDER BY d) + FROM generate_series(1, ${DIMS}) AS d)::vector(${DIMS}) AS v + FROM generate_series(0, ${BASES - 1}) AS b`, + ); + await client.query( + `CREATE TEMP TABLE cal_vectors AS + SELECT n AS id, x.v + y.v AS v + FROM generate_series(0, ${VECTORS - 1}) AS n + JOIN cal_base x ON x.b = n % ${BASES} + JOIN cal_base y ON y.b = n / ${BASES}`, + ); + await client.query('ANALYZE cal_vectors'); +} + +async function vectorWork(client: pg.Client): Promise { + for (let q = 1; q <= VECTOR_QUERIES; q++) { + await client.query( + `SELECT id FROM cal_vectors + ORDER BY v <=> (SELECT v FROM cal_vectors WHERE id = $1) LIMIT 50`, + [q * 997 - 1], + ); + } +} + +/** This machine's CPU, as the snapshot bench names it. */ +export function machine(): string { + const cpus = os.cpus(); + return `${cpus[0]?.model ?? 'unknown'} × ${cpus.length}, ${Math.round(os.totalmem() / 2 ** 30)} GB`; +} + +/** + * Times the reference workload's parts. `superuserUrl` is a superuser's connection to the + * maintenance database: a scratch database is made for the SQL parts (with pgvector) and dropped + * after. + */ +export async function measureComponents(superuserUrl: string): Promise { + const checksum = cpuWork(); + if (checksum !== CPU_CHECKSUM) { + throw new Error( + `calibration: cpuWork() returned ${checksum}, not ${CPU_CHECKSUM}: the workload changed, so REFERENCE_MS must be re-pinned`, + ); + } + const cpu = await fastest(async () => { + cpuWork(); + }); + + const name = `kept_cal_${Date.now().toString(36)}${Math.floor(Math.random() * 36 ** 4).toString(36)}`; + const admin = new pg.Client({ connectionString: superuserUrl }); + await admin.connect(); + try { + await admin.query(`CREATE DATABASE ${name}`); + const url = new URL(superuserUrl); + url.pathname = `/${name}`; + // As the server's pools (src/db/pools.ts): JIT off. Temporary tables in memory. + const client = new pg.Client({ connectionString: url.toString(), options: CONNECTION_OPTIONS }); + await client.connect(); + try { + await client.query(`SET temp_buffers = '256MB'`); + await client.query('CREATE EXTENSION IF NOT EXISTS vector'); + const db = await fastest(() => dbWork(client)); + await vectorSetup(client); + const vector = await fastest(() => vectorWork(client)); + return { cpu, db, vector }; + } finally { + await client.end(); + } + } finally { + await admin.query(`DROP DATABASE IF EXISTS ${name} WITH (FORCE)`).catch(() => {}); + await admin.end(); + } +} + +/** The workload timed and compared with REFERENCE_MS. */ +export async function measureCalibration(superuserUrl: string): Promise { + return calibrationOf(await measureComponents(superuserUrl), undefined, machine()); +} diff --git a/apps/server/test/perf/calibration.ts b/apps/server/test/perf/calibration.ts new file mode 100644 index 00000000..f06d907f --- /dev/null +++ b/apps/server/test/perf/calibration.ts @@ -0,0 +1,111 @@ +// The runner's speed for the performance checks (test/perf; issue #159). The limits are fixed +// milliseconds, and the nightly job lands on GitHub runners of different speeds: the same commit +// passed on one and failed on another a day later, with everything about twice as slow. +// +// So the run first times a fixed reference workload (calibrate.ts: pure JavaScript, plain SQL and +// an exact vector scan, none of it Kept's code), compares it with REFERENCE_MS, and multiplies +// every millisecond limit by the resulting factor (never below 1). A real regression still fails: +// it slows the code under test, not the reference work, so the factor doesn't grow with it. +// +// This file is the arithmetic only, with no database, so the normal suite unit-tests it +// (test/perf-calibration.test.ts). + +/** The reference workload's three parts (calibrate.ts). */ +export const COMPONENTS = ['cpu', 'db', 'vector'] as const; +export type Component = (typeof COMPONENTS)[number]; +export type ComponentMs = Record; + +/** + * The reference workload on the reference runner, each part's fastest of CALIBRATION_RUNS, in ms: + * a fast GitHub runner (AMD EPYC 9V45), the one the nightly passed on (Oct 10 and 12). + * + * **Inferred, not yet measured on that runner**, because the workload is new: timed on an M1 Pro + * (cpu 273.1, db 626.9, vector 401.8 ms, in a full local `ci-local.sh --only perf` run, 2026-10-17) + * and divided by 1.42, how much slower that M1 Pro was than the 9V45 at the same fixed work in + * the same run: the snapshot bench's full snapshot as owner, p50 453.5 ms against 327.2 and + * 311.5 ms on Oct 10 and 12 (the bench is not scaled, and its p50 is steady). Re-pin from a 9V45 + * night's .tmp/perf/calibration.json (`measuredMs`, beside `machine`), and whenever calibrate.ts + * changes (cpuWork()'s checksum guards its JavaScript part). + */ +export const REFERENCE_MS: ComponentMs = { cpu: 192.3, db: 441.5, vector: 283.0 }; + +/** Past this the run isn't evidence of anything: the limits stop growing and checks fail. */ +export const MAX_FACTOR = 3; + +export type Calibration = { + /** This run's fastest time per part, ms. */ + measuredMs: ComponentMs; + referenceMs: ComponentMs; + /** measured / reference per part. */ + ratios: ComponentMs; + /** The geometric mean of the ratios, before clamping. */ + raw: number; + /** What the limits are multiplied by: raw, clamped to [1, MAX_FACTOR], two decimals. */ + factor: number; + machine?: string; +}; + +const round = (n: number, places: number) => { + const p = 10 ** places; + return Math.round(n * p) / p; +}; + +/** The speed factor from this run's timings. Throws on a missing or non-positive timing. */ +export function calibrationOf( + measuredMs: ComponentMs, + referenceMs: ComponentMs = REFERENCE_MS, + machine?: string, +): Calibration { + for (const c of COMPONENTS) { + for (const [what, v] of [ + ['measured', measuredMs[c]], + ['reference', referenceMs[c]], + ] as const) { + if (!Number.isFinite(v) || v <= 0) throw new Error(`calibration: ${what} ${c} is ${v}`); + } + } + const ratios = Object.fromEntries( + COMPONENTS.map((c) => [c, round(measuredMs[c] / referenceMs[c], 3)]), + ) as ComponentMs; + // Geometric mean: each part counts the same, whatever its length in ms. + const raw = Math.exp( + COMPONENTS.reduce((sum, c) => sum + Math.log(measuredMs[c] / referenceMs[c]), 0) / + COMPONENTS.length, + ); + const factor = round(Math.min(MAX_FACTOR, Math.max(1, raw)), 2); + return { + measuredMs, + referenceMs, + ratios, + raw: round(raw, 3), + factor, + ...(machine ? { machine } : {}), + }; +} + +/** A millisecond limit on this runner: `baseMs` × the factor (never below 1), to 0.1 ms. */ +export function scaledLimit(baseMs: number, factor: number): number { + return round(baseMs * Math.min(MAX_FACTOR, Math.max(1, factor)), 1); +} + +export type Verdict = { + measuredMs: number; + limitMs: number; + factor: number; + scaledLimitMs: number; + pass: boolean; + message: string; +}; + +/** One check: `measuredMs` against `baseMs` scaled by `factor`. */ +export function judge(name: string, measuredMs: number, baseMs: number, factor: number): Verdict { + const scaledLimitMs = scaledLimit(baseMs, factor); + return { + measuredMs, + limitMs: baseMs, + factor, + scaledLimitMs, + pass: measuredMs < scaledLimitMs, + message: `${name}: ${measuredMs} ms against ${baseMs} ms × ${factor} (runner speed) = ${scaledLimitMs} ms`, + }; +} diff --git a/apps/server/test/perf/global-setup.ts b/apps/server/test/perf/global-setup.ts new file mode 100644 index 00000000..5706b494 --- /dev/null +++ b/apps/server/test/perf/global-setup.ts @@ -0,0 +1,31 @@ +import { mkdirSync, writeFileSync } from 'node:fs'; +import path from 'node:path'; +import type { TestProject } from 'vitest/node'; +import { packageRoot } from '../../src/package-root.js'; +import { measureCalibration } from './calibrate.js'; +import type { Calibration } from './calibration.js'; + +declare module 'vitest' { + export interface ProvidedContext { + /** The runner's speed for this perf run (test/perf/calibration.ts; issue #159). */ + keptPerfCalibration: Calibration; + } +} + +const SUPERUSER_URL = 'postgres://postgres:postgres@localhost:5452/postgres'; + +// The perf run's second global setup (vitest.perf.config.ts), after test/global-setup.ts: times +// the reference workload once, before any check, hands it to every file and writes it beside the +// checks' figures (.tmp/perf/calibration.json). +export async function setup(project: TestProject): Promise { + const calibration = await measureCalibration(SUPERUSER_URL); + project.provide('keptPerfCalibration', calibration); + const dir = path.join(packageRoot(), '../../.tmp/perf'); + mkdirSync(dir, { recursive: true }); + const file = path.join(dir, 'calibration.json'); + writeFileSync( + file, + `${JSON.stringify({ at: new Date().toISOString(), calibration }, null, 2)}\n`, + ); + console.log(`perf calibration: ${JSON.stringify(calibration)} → ${file}`); +} diff --git a/apps/server/test/perf/limits.ts b/apps/server/test/perf/limits.ts new file mode 100644 index 00000000..7680c211 --- /dev/null +++ b/apps/server/test/perf/limits.ts @@ -0,0 +1,25 @@ +import { expect, inject } from 'vitest'; +import { type Calibration, judge } from './calibration.js'; + +// The checks' limits on this runner (issue #159): each file's LIMITS are the reference runner's +// milliseconds; `under()` scales one by the run's speed factor (test/perf/global-setup.ts), +// records the verdict in the file's results (`limits`, beside the figures in its JSON) and fails +// with the factor and the scaled limit in the message. + +/** This run's calibration, measured once before any file. */ +export function calibration(): Calibration { + return inject('keptPerfCalibration'); +} + +/** Asserts `measuredMs` is under `baseMs` × the runner's factor, and records the verdict. */ +export function under( + results: Record, + name: string, + measuredMs: number, + baseMs: number, +): void { + const v = judge(name, measuredMs, baseMs, calibration().factor); + const { message: _message, ...recorded } = v; + results.limits = { ...(results.limits as Record | undefined), [name]: recorded }; + expect(measuredMs, v.message).toBeLessThan(v.scaledLimitMs); +} diff --git a/apps/server/test/perf/step3.perf.test.ts b/apps/server/test/perf/step3.perf.test.ts index 4b3238e3..0202814e 100644 --- a/apps/server/test/perf/step3.perf.test.ts +++ b/apps/server/test/perf/step3.perf.test.ts @@ -11,6 +11,7 @@ import { inbox } from '../inbox.js'; import { call, join, type Person, peopleApp, person, type RecordedJob } from '../people.js'; import { captureOp, syncOps } from '../sync-ops.js'; import { createLocation, type Loc, ok, own, place } from '../things.js'; +import { calibration, under } from './limits.js'; // Step 3's performance checks (plan T32 "Perf", full mode only: scripts/ci-local.sh `perf`, and // `pnpm --filter @kept/server exec vitest run --config vitest.perf.config.ts`). The normal test @@ -33,6 +34,7 @@ import { createLocation, type Loc, ok, own, place } from '../things.js'; // so that a real regression fails and ordinary machine noise doesn't: the batch's p95 was // 855–1,089 ms (limit 1.5 s), the inbox page's 19–20 ms (limit 100 ms, well under §3.1's page // p95 of 300 ms), and a 200-row import chunk 2.9–3.5 s, about 63–68 rows a second (limit 10 s). +// Each is multiplied by the runner's speed factor (test/perf/calibration.ts, issue #159). const BATCH_OPS = 50; const BATCH_WARMUP = 3; @@ -82,7 +84,10 @@ afterAll(async () => { const dir = path.join(packageRoot(), '../../.tmp/perf'); mkdirSync(dir, { recursive: true }); const file = path.join(dir, 'step3-perf.json'); - writeFileSync(file, `${JSON.stringify({ at: new Date().toISOString(), results }, null, 2)}\n`); + writeFileSync( + file, + `${JSON.stringify({ at: new Date().toISOString(), calibration: calibration(), results }, null, 2)}\n`, + ); console.log(`step3 perf: ${JSON.stringify(results)} → ${file}`); }); @@ -105,7 +110,7 @@ describe('step-3 performance (plan T32, full mode only)', () => { } const s = stats(samples); results.syncBatch50 = s; - expect(s.p95).toBeLessThan(LIMITS.batchP95Ms); + under(results, 'batchP95Ms', s.p95, LIMITS.batchP95Ms); }, 600_000); it(`answers the inbox's first page at ${INBOX_OPEN} open items with p95 under ${LIMITS.inboxPageP95Ms} ms`, async () => { @@ -149,7 +154,7 @@ describe('step-3 performance (plan T32, full mode only)', () => { } const s = stats(samples); results.inboxFirstPage500 = s; - expect(s.p95).toBeLessThan(LIMITS.inboxPageP95Ms); + under(results, 'inboxPageP95Ms', s.p95, LIMITS.inboxPageP95Ms); }, 300_000); it(`imports a ${CHUNK}-row CSV chunk in under ${LIMITS.importChunkMaxMs} ms`, async () => { const sent: RecordedJob[] = []; @@ -220,6 +225,6 @@ describe('step-3 performance (plan T32, full mode only)', () => { } const s = stats(chunks); results.importChunk200 = { ...s, rowsPerSecond: Math.round((CHUNK / s.p50) * 1000 * 10) / 10 }; - expect(s.max).toBeLessThan(LIMITS.importChunkMaxMs); + under(results, 'importChunkMaxMs', s.max, LIMITS.importChunkMaxMs); }, 600_000); }); diff --git a/apps/server/test/perf/step4.perf.test.ts b/apps/server/test/perf/step4.perf.test.ts index cf51b779..afc746e5 100644 --- a/apps/server/test/perf/step4.perf.test.ts +++ b/apps/server/test/perf/step4.perf.test.ts @@ -10,6 +10,7 @@ import { type TestDb, testDb } from '../db.js'; import { call, type Person, peopleApp } from '../people.js'; import { type Loc, ok, own } from '../things.js'; import { seedHousehold, THINGS } from './household.js'; +import { calibration, under } from './limits.js'; import { stats, timed } from './timing.js'; // Step 4's performance checks (plan T30 "Perf", full mode only: scripts/ci-local.sh `perf`, and @@ -54,6 +55,7 @@ import { stats, timed } from './timing.js'; // to back runs at load 5–14. // - A full scan pass: 10 s, tighter than the plan's 20 s (the worst pass measured 2.8 s). // - The count: the plan's 20 ms (p95 measured 5.4–6.2 ms). +// Each is multiplied by the runner's speed factor (test/perf/calibration.ts, issue #159). const READ_NOTIFICATIONS = 1_500; const HOME_WARMUP = 5; @@ -97,7 +99,10 @@ afterAll(async () => { const dir = path.join(packageRoot(), '../../.tmp/perf'); mkdirSync(dir, { recursive: true }); const file = path.join(dir, 'step4.json'); - writeFileSync(file, `${JSON.stringify({ at: new Date().toISOString(), results }, null, 2)}\n`); + writeFileSync( + file, + `${JSON.stringify({ at: new Date().toISOString(), calibration: calibration(), results }, null, 2)}\n`, + ); console.log(`step4 perf: ${JSON.stringify(results)} → ${file}`); }); @@ -119,7 +124,7 @@ describe('step-4 performance (plan T30, full mode only)', () => { expect(res.statusCode, res.body).toBe(200); }); results.agendaFirstPage = agenda; - expect(s.p95).toBeLessThan(LIMITS.homeP95Ms); + under(results, 'homeP95Ms', s.p95, LIMITS.homeP95Ms); }, 300_000); // D240: Home's own read beside /home (the cards' flags and value, the tiles' first items, the @@ -134,7 +139,7 @@ describe('step-4 performance (plan T30, full mode only)', () => { expect(res.statusCode, res.body).toBe(200); }); results.homeOverview = s; - expect(s.p95).toBeLessThan(LIMITS.homeP95Ms); + under(results, 'homeOverviewP95Ms', s.p95, LIMITS.homeP95Ms); }, 300_000); it(`runs a full reminder scan pass in under ${LIMITS.scanPassMaxMs} ms`, async () => { @@ -167,8 +172,8 @@ describe('step-4 performance (plan T30, full mode only)', () => { deliverJobs: jobs, }; results.scanSteadyPass = stats(steady); - expect(s.max).toBeLessThan(LIMITS.scanPassMaxMs); - expect(stats(steady).max).toBeLessThan(LIMITS.scanPassMaxMs); + under(results, 'scanPassMaxMs', s.max, LIMITS.scanPassMaxMs); + under(results, 'scanSteadyPassMaxMs', stats(steady).max, LIMITS.scanPassMaxMs); }, 600_000); it(`counts the owner's unread notifications with p95 under ${LIMITS.notificationCountP95Ms} ms`, async () => { @@ -200,6 +205,6 @@ describe('step-4 performance (plan T30, full mode only)', () => { expect(res.statusCode, res.body).toBe(200); }); results.notificationCount = { ...s, total: mine[0]?.total, unread }; - expect(s.p95).toBeLessThan(LIMITS.notificationCountP95Ms); + under(results, 'notificationCountP95Ms', s.p95, LIMITS.notificationCountP95Ms); }, 300_000); }); diff --git a/apps/server/test/perf/steps6-8.perf.test.ts b/apps/server/test/perf/steps6-8.perf.test.ts index 4cb2528f..04fbff10 100644 --- a/apps/server/test/perf/steps6-8.perf.test.ts +++ b/apps/server/test/perf/steps6-8.perf.test.ts @@ -21,6 +21,7 @@ import { type TestFiles, testFiles } from '../files.js'; import { call, type Person, peopleApp, type RecordedJob } from '../people.js'; import { createLocation, type Loc, ok, own } from '../things.js'; import { seedHousehold, THINGS } from './household.js'; +import { calibration, under } from './limits.js'; import { timed } from './timing.js'; // Steps 6–8's performance checks (the final check for steps 5–8; step-6 plan T26 "Perf", step-7 @@ -46,6 +47,7 @@ import { timed } from './timing.js'; // process's RSS growth recorded; limited at 10 minutes. // - The Homebox import of the committed v0.26.2 `home` fixture into a new location: upload, // inspect and dry run, then the job: times recorded; limited at 2 minutes. +// Each limit is multiplied by the runner's speed factor (test/perf/calibration.ts, issue #159). // The requests go through the app in-process (fastify inject): server time, no network. const LIMITS = { @@ -212,7 +214,10 @@ afterAll(async () => { const dir = path.join(packageRoot(), '../../.tmp/perf'); mkdirSync(dir, { recursive: true }); const file = path.join(dir, 'steps6-8.json'); - writeFileSync(file, `${JSON.stringify({ at: new Date().toISOString(), results }, null, 2)}\n`); + writeFileSync( + file, + `${JSON.stringify({ at: new Date().toISOString(), calibration: calibration(), results }, null, 2)}\n`, + ); console.log(`steps6-8 perf: ${JSON.stringify(results)} → ${file}`); }); @@ -237,7 +242,7 @@ describe('steps 6–8 performance (final check, full mode only)', () => { await search(SHARED); })), }; - expect(s.p95).toBeLessThan(LIMITS.searchP95Ms); + under(results, 'searchKeywordP95Ms', s.p95, LIMITS.searchP95Ms); }, TEST_MS, ); @@ -266,7 +271,7 @@ describe('steps 6–8 performance (final check, full mode only)', () => { await search('the thing for the TV'); })), }; - expect(s.p95).toBeLessThan(LIMITS.searchP95Ms); + under(results, 'searchSemanticP95Ms', s.p95, LIMITS.searchP95Ms); }, TEST_MS, ); @@ -283,7 +288,7 @@ describe('steps 6–8 performance (final check, full mode only)', () => { const s = await timed(WARMUP, RUNS, once(RARE)); results.mcpWhereIs = { q: RARE, ...s }; results.mcpWhereIsEveryRow = { q: SHARED, ...(await timed(WARMUP, RUNS, once(SHARED))) }; - expect(s.p95).toBeLessThan(LIMITS.mcpWhereIsP95Ms); + under(results, 'mcpWhereIsP95Ms', s.p95, LIMITS.mcpWhereIsP95Ms); }, TEST_MS, ); @@ -323,7 +328,7 @@ describe('steps 6–8 performance (final check, full mode only)', () => { rssBeforeMb: mb(rssBefore), rssPeakMb: mb(rssPeak), }; - expect(ms).toBeLessThan(LIMITS.exportMaxMs); + under(results, 'exportMaxMs', ms, LIMITS.exportMaxMs); }, 900_000); it(`imports the Homebox v0.26.2 home fixture in under ${LIMITS.homeboxImportMaxMs / 1000} s`, async () => { @@ -389,6 +394,6 @@ describe('steps 6–8 performance (final check, full mode only)', () => { jobMs: Math.round(done - prepared), totalMs: Math.round(done - started), }; - expect(done - started).toBeLessThan(LIMITS.homeboxImportMaxMs); + under(results, 'homeboxImportMaxMs', Math.round(done - started), LIMITS.homeboxImportMaxMs); }, 300_000); }); diff --git a/apps/server/test/perf/vehicles.perf.test.ts b/apps/server/test/perf/vehicles.perf.test.ts index 69b7e310..fd0297cc 100644 --- a/apps/server/test/perf/vehicles.perf.test.ts +++ b/apps/server/test/perf/vehicles.perf.test.ts @@ -12,6 +12,7 @@ import { type TestFiles, testFiles } from '../files.js'; import { call, join, type Person, peopleApp, type RecordedJob } from '../people.js'; import { builtinType, createLocation, createThing, type Loc, ok, own } from '../things.js'; import { seedHousehold } from './household.js'; +import { calibration, under } from './limits.js'; import { timed } from './timing.js'; // Step 5's performance checks (plan T25 "Perf", full mode only: scripts/ci-local.sh `perf`, and @@ -41,6 +42,10 @@ import { timed } from './timing.js'; // 0071): Home p95 92.0 ms, the agenda's first page p95 122.1 ms. So 110.4 ms and 146.5 ms. // Measured before the vehicles are added too, on the same rows in the same run, and recorded: // the ratio is the fairer comparison on a loaded machine; the gate is the recorded figure. +// Like every limit here it is multiplied by the runner's speed factor (test/perf/calibration.ts, +// issue #159), and it needs no noise floor of its own: 20% of those figures is 18–24 ms, and +// they were taken on an M1 Pro under load, slower than the reference runner (the fast nights +// measured Home at p95 53–64 ms here). // - The vehicles list, all 50 in one page: p95 < 200 ms. // - The Corolla's running costs over the last 60 months (600 fills, 60 services): p95 < 200 ms. // - Its fuel summary over 600 fills: p95 < 100 ms. @@ -237,7 +242,10 @@ afterAll(async () => { const dir = path.join(packageRoot(), '../../.tmp/perf'); mkdirSync(dir, { recursive: true }); const file = path.join(dir, 'step5.json'); - writeFileSync(file, `${JSON.stringify({ at: new Date().toISOString(), results }, null, 2)}\n`); + writeFileSync( + file, + `${JSON.stringify({ at: new Date().toISOString(), calibration: calibration(), results }, null, 2)}\n`, + ); console.log(`step5 perf: ${JSON.stringify(results)} → ${file}`); }); @@ -257,8 +265,8 @@ describe('step-5 performance (plan T25, full mode only)', () => { agendaFirstPage: Math.round((agendaStats.p95 / before.agendaFirstPage.p95) * 100) / 100, }, }; - expect(homeStats.p95).toBeLessThan(LIMITS.homeP95Ms); - expect(agendaStats.p95).toBeLessThan(LIMITS.agendaP95Ms); + under(results, 'homeP95Ms', homeStats.p95, LIMITS.homeP95Ms); + under(results, 'agendaP95Ms', agendaStats.p95, LIMITS.agendaP95Ms); }, 300_000); it(`lists 50 vehicles in one page with p95 under ${LIMITS.vehiclesP95Ms} ms`, async () => { @@ -273,7 +281,7 @@ describe('step-5 performance (plan T25, full mode only)', () => { expect(res.statusCode, res.body).toBe(200); }); results.vehicles = s; - expect(s.p95).toBeLessThan(LIMITS.vehiclesP95Ms); + under(results, 'vehiclesP95Ms', s.p95, LIMITS.vehiclesP95Ms); }, 300_000); it(`gives five years of running costs with p95 under ${LIMITS.costsP95Ms} ms`, async () => { @@ -294,7 +302,7 @@ describe('step-5 performance (plan T25, full mode only)', () => { expect(res.statusCode, res.body).toBe(200); }); results.costs5y = s; - expect(s.p95).toBeLessThan(LIMITS.costsP95Ms); + under(results, 'costsP95Ms', s.p95, LIMITS.costsP95Ms); }, 300_000); it(`summarises 600 fills with p95 under ${LIMITS.fuelSummaryP95Ms} ms`, async () => { @@ -306,7 +314,7 @@ describe('step-5 performance (plan T25, full mode only)', () => { expect(res.statusCode, res.body).toBe(200); }); results.fuelSummary = s; - expect(s.p95).toBeLessThan(LIMITS.fuelSummaryP95Ms); + under(results, 'fuelSummaryP95Ms', s.p95, LIMITS.fuelSummaryP95Ms); }, 300_000); it(`opens a thing with 3 meters with p95 under ${LIMITS.thingPageP95Ms} ms`, async () => { @@ -322,7 +330,7 @@ describe('step-5 performance (plan T25, full mode only)', () => { expect(res.statusCode, res.body).toBe(200); }); results.thingPage3Meters = s; - expect(s.p95).toBeLessThan(LIMITS.thingPageP95Ms); + under(results, 'thingPageP95Ms', s.p95, LIMITS.thingPageP95Ms); }, 300_000); it(`answers Insights over 10,000 valued things with p95 under ${LIMITS.insightsP95Ms} ms`, async () => { @@ -353,7 +361,7 @@ describe('step-5 performance (plan T25, full mode only)', () => { expect(res.statusCode, res.body).toBe(200); }); results.insights = s; - expect(s.p95).toBeLessThan(LIMITS.insightsP95Ms); + under(results, 'insightsP95Ms', s.p95, LIMITS.insightsP95Ms); }, 300_000); it(`renders five years' history report under the renderer's ${RENDER_MEMORY_MB} MB limit`, async () => { diff --git a/apps/server/vitest.perf.config.ts b/apps/server/vitest.perf.config.ts index d2d7e70b..25e05dd1 100644 --- a/apps/server/vitest.perf.config.ts +++ b/apps/server/vitest.perf.config.ts @@ -4,13 +4,15 @@ import base from './vitest.config.ts'; // The performance checks (plan T32; test/perf), full mode only: scripts/ci-local.sh `perf`. The // same setup as the normal run (a database cloned from the run's template), one file at a time. // Built by hand rather than with mergeConfig, which would concatenate the base's exclude (the one -// that leaves test/perf out of `pnpm test`) into this one. +// that leaves test/perf out of `pnpm test`) into this one. A second global setup times the +// runner's reference workload once, before any file (test/perf/global-setup.ts, issue #159). export default defineConfig({ test: { ...base.test, name: '@kept/server perf', include: ['test/perf/**/*.perf.test.ts'], exclude: configDefaults.exclude, + globalSetup: ['./test/global-setup.ts', './test/perf/global-setup.ts'], fileParallelism: false, }, }); diff --git a/scripts/ci-local.sh b/scripts/ci-local.sh index 0a4cb35e..02589f11 100644 --- a/scripts/ci-local.sh +++ b/scripts/ci-local.sh @@ -539,6 +539,7 @@ step_backup() { # page, through the RLS bench (its own scratch database; exits 1 over budget), then # apps/server/test/perf (a 50-op sync batch's p95, the inbox's first page at 500 open items). # Results: .tmp/perf/. Numbers taken under load are not evidence; run it on a quiet machine. +# test/perf's limits scale with the machine's speed, timed first (.tmp/perf/calibration.json, #159). step_perf() { mkdir -p "$repo/.tmp/perf" pnpm --filter @kept/server bench -- --snapshot-only --out "$repo/.tmp/perf/snapshot-bench.json"