Merge pull request 'test(perf): measure what concurrent hashing actually costs a bystander request (#163)' (#172) from feature/163-measure-hash-latency into main

Reviewed-on: #172

backend/package.json

@@ -5,7 +5,7 @@
   "main": "dist/server.js",
   "scripts": {
     "build": "tsc",
-    "lint": "eslint src",
+    "lint": "eslint src scripts",
     "start": "node dist/server.js",
     "dev": "tsx watch src/server.ts",
     "test": "npm run test:unit",
@@ -15,6 +15,7 @@
     "test:integration": "jest -c jest.integration.config.js --runInBand",
     "test:integration:json": "jest -c jest.integration.config.js --runInBand --json --outputFile=integration-results.json",
     "test:integration:cov": "jest -c jest.integration.config.js --runInBand --coverage --forceExit",
+    "bench:hashing": "tsx scripts/bench-hash-latency.ts",
     "db:test:up": "docker compose -f docker-compose.test.yml up -d",
     "db:test:down": "docker compose -f docker-compose.test.yml down -v",
     "migrate:up": "node migrate.js up",

backend/scripts/bench-hash-latency.ts

@@ -0,0 +1,201 @@
+/**
+ * What does concurrent password hashing cost a request that is not hashing?
+ *
+ * #163 originally claimed `bcryptjs` blocks the event loop and that every login
+ * stalls every other request in flight. That claim was wrong — the asynchronous
+ * API chunks its work and yields between rounds — but a smaller effect is real:
+ * the chunks are coarse, and N simultaneous registrations still queue N hashes
+ * worth of CPU that has to come from somewhere.
+ *
+ * This measures that effect rather than arguing about it, so any future change
+ * to hashing is justified by a number and can be checked by re-running this.
+ *
+ * Method
+ * ------
+ * The probe is `GET /api/customers/me` with no session cookie. It is chosen for
+ * doing almost nothing: it rejects on a missing cookie before touching the
+ * database, so nearly all of its measured latency is time spent waiting for the
+ * event loop rather than work of its own. A heavier probe would measure the
+ * database instead, which is not the question.
+ *
+ * The load is real registrations against the real route, because the point is
+ * what a deployed server does, not what bcrypt does on a bench.
+ *
+ * Registrations create real rows. They are deleted afterwards — this is
+ * normally pointed at a development database that nothing truncates, and a
+ * benchmark that quietly adds hundreds of customers every run would be its own
+ * small problem.
+ *
+ * Usage
+ * -----
+ *   npm run bench:hashing
+ *
+ * Honours BENCH_URL, BENCH_CONCURRENCY, BENCH_ROUNDS, and the usual PG* vars
+ * for the cleanup connection.
+ */
+
+import { Pool } from 'pg';
+
+const BASE_URL = process.env.BENCH_URL ?? 'http://localhost:3001';
+
+// Eight, because that is what Playwright uses on this machine — half the cores
+// — and the end-to-end suite registering customers in parallel is one of the
+// two places #163 suggested the cost might actually show up.
+const CONCURRENCY = Number(process.env.BENCH_CONCURRENCY ?? 8);
+const ROUNDS = Number(process.env.BENCH_ROUNDS ?? 5);
+
+// Long enough for the baseline to see past a single slow sample, short enough
+// that the whole run stays under a minute.
+const BASELINE_MS = 3000;
+
+// Marks every row this script creates, so cleanup can be exact rather than
+// date-based. Anything left behind by a crashed run is removed by the next one.
+const EMAIL_PREFIX = 'bench-hash-';
+
+interface Stats {
+  count: number;
+  p50: number;
+  p95: number;
+  max: number;
+}
+
+function summarise(samples: number[]): Stats {
+  const sorted = [...samples].sort((a, b) => a - b);
+  const at = (fraction: number): number => {
+    // Nearest-rank, which needs no interpolation and cannot invent a value that
+    // was never measured.
+    const index = Math.min(sorted.length - 1, Math.ceil(fraction * sorted.length) - 1);
+    return sorted[Math.max(0, index)] ?? 0;
+  };
+  return {
+    count: sorted.length,
+    p50: at(0.5),
+    p95: at(0.95),
+    max: sorted[sorted.length - 1] ?? 0
+  };
+}
+
+async function probe(): Promise<number> {
+  const started = performance.now();
+  const res = await fetch(`${BASE_URL}/api/customers/me`);
+  // Drained rather than ignored: leaving the body unread would stop the clock
+  // before the response has actually arrived.
+  await res.arrayBuffer();
+  return performance.now() - started;
+}
+
+async function register(index: number): Promise<number> {
+  const started = performance.now();
+  const res = await fetch(`${BASE_URL}/api/customers/register`, {
+    method: 'POST',
+    headers: { 'content-type': 'application/json' },
+    body: JSON.stringify({
+      email: `${EMAIL_PREFIX}${Date.now().toString(36)}-${index}@example.com`,
+      // Not a credential: it hashes these accounts into existence and deletes
+      // them again at the end of the run. The cost of hashing is the whole
+      // point, so it cannot be shortened or faked.
+      // eslint-disable-next-line sonarjs/no-hardcoded-passwords
+      password: 'benchmark-password',
+      firstName: 'Bench',
+      lastName: 'Mark'
+    })
+  });
+  await res.arrayBuffer();
+  if (!res.ok) throw new Error(`registration failed with ${res.status}`);
+  return performance.now() - started;
+}
+
+/** Probes continuously until `until` resolves, so the samples span the load. */
+async function probeUntil(until: Promise<unknown>): Promise<number[]> {
+  const samples: number[] = [];
+  let done = false;
+  void until.then(
+    () => { done = true; },
+    () => { done = true; }
+  );
+  while (!done) {
+    samples.push(await probe());
+  }
+  return samples;
+}
+
+async function measureBaseline(): Promise<number[]> {
+  const samples: number[] = [];
+  const deadline = performance.now() + BASELINE_MS;
+  while (performance.now() < deadline) {
+    samples.push(await probe());
+  }
+  return samples;
+}
+
+async function cleanup(): Promise<number> {
+  const pool = new Pool();
+  try {
+    // Sessions and tokens reference the customer, so they go first — the
+    // registration route creates one of each.
+    await pool.query(
+      `DELETE FROM customer_sessions WHERE customer_id IN (SELECT id FROM customers WHERE email LIKE $1)`,
+      [`${EMAIL_PREFIX}%`]
+    );
+    await pool.query(
+      `DELETE FROM customer_tokens WHERE customer_id IN (SELECT id FROM customers WHERE email LIKE $1)`,
+      [`${EMAIL_PREFIX}%`]
+    );
+    const { rowCount } = await pool.query(`DELETE FROM customers WHERE email LIKE $1`, [`${EMAIL_PREFIX}%`]);
+    return rowCount ?? 0;
+  } finally {
+    await pool.end();
+  }
+}
+
+function report(label: string, stats: Stats): void {
+  console.info(
+    `${label.padEnd(28)} n=${String(stats.count).padStart(4)}  ` +
+      `p50=${stats.p50.toFixed(1).padStart(7)} ms  ` +
+      `p95=${stats.p95.toFixed(1).padStart(7)} ms  ` +
+      `max=${stats.max.toFixed(1).padStart(7)} ms`
+  );
+}
+
+async function main(): Promise<void> {
+  console.info(`[bench] ${BASE_URL}, ${CONCURRENCY} concurrent registrations x ${ROUNDS} rounds`);
+
+  // A cold first request pays for connection setup and JIT, which would land
+  // entirely in the baseline and flatter the comparison.
+  for (let i = 0; i < 10; i++) await probe();
+
+  const baseline = await measureBaseline();
+  report('idle', summarise(baseline));
+
+  const underLoad: number[] = [];
+  const registrations: number[] = [];
+
+  for (let round = 0; round < ROUNDS; round++) {
+    const load = Promise.all(
+      Array.from({ length: CONCURRENCY }, (_unused, index) => register(round * CONCURRENCY + index))
+    );
+    const [samples, times] = await Promise.all([probeUntil(load), load]);
+    underLoad.push(...samples);
+    registrations.push(...times);
+  }
+
+  report(`under ${CONCURRENCY} registrations`, summarise(underLoad));
+  report('the registrations', summarise(registrations));
+
+  const idle = summarise(baseline);
+  const loaded = summarise(underLoad);
+  console.info(
+    `\n[bench] a bystander request costs ` +
+      `${(loaded.p50 - idle.p50).toFixed(1)} ms more at p50, ` +
+      `${(loaded.p95 - idle.p95).toFixed(1)} ms more at p95, ` +
+      `worst case ${loaded.max.toFixed(1)} ms`
+  );
+
+  const removed = await cleanup();
+  console.info(`[bench] removed ${removed} benchmark customers`);
+}
+
+main().catch((error: unknown) => {
+  console.error('[bench] failed:', error);
+  process.exitCode = 1;
+});