test(perf): measure what concurrent hashing actually costs a bystander request (#163) #172
@@ -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",
|
||||
|
||||
@@ -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;
|
||||
});
|
||||
Reference in New Issue
Block a user