diff --git a/backend/package.json b/backend/package.json index 64bc930..924433d 100755 --- a/backend/package.json +++ b/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", diff --git a/backend/scripts/bench-hash-latency.ts b/backend/scripts/bench-hash-latency.ts new file mode 100644 index 0000000..2fb28dd --- /dev/null +++ b/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 { + 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 { + 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): Promise { + 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 { + const samples: number[] = []; + const deadline = performance.now() + BASELINE_MS; + while (performance.now() < deadline) { + samples.push(await probe()); + } + return samples; +} + +async function cleanup(): Promise { + 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 { + 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; +});