/** * What each bounded operation ACTUALLY takes — the measurement every bound is sized from. * * ── Why a bound needs its measurement kept beside it ───────────────────────── * A bare number teaches nothing and rots in silence. "180 seconds" cannot be judged: is it * ten times the normal duration, or a hundred? Only one of those is a bound; the other is a * hang dressed up as one. The suite this module serves had a sign-in bounded at 3 minutes * for an operation that measures 1.4s, so its single job — turning a hang into a named * failure fast — was done fifty times too slowly to be worth anything. * * So every bound in these harnesses is written as `measured normal → bound → margin`, and * this module is how the "measured normal" half is obtained and re-obtained. Run any suite * with `E2E_TIMINGS=1` and it prints, at the end, what each named operation took and how * much headroom its bound still has. A future reader who suspects a number has gone stale * does not have to believe this file's comments: they can re-run the measurement. * * Passive by default — a `Date.now()` per wait, and nothing printed unless asked. */ /** One observation of one named operation. */ interface Sample { readonly ms: number; /** Sizing a bound from a FAILED attempt would size it from the bound itself. */ readonly ok: boolean; /** The bound in force, so the report can show the headroom rather than make one guess it. */ readonly bound: number; } const samples = new Map(); export function record(what: string, ms: number, ok: boolean, bound: number): void { const seen = samples.get(what); if (seen === undefined) samples.set(what, [{ ms, ok, bound }]); else seen.push({ ms, ok, bound }); } /** * Run a wait under `bound`, recording what it took under the stable name `what`. * * The bound is handed TO the task rather than raced against it, deliberately: Playwright's * own timeout reports the call log ("waiting for locator(…)"), and a race would replace that * with a message naming only the enclosure. What this adds is the measurement and a stable * name — not a second, competing deadline. * * The name must be stable across runs (no identifiers, no ports) or the table fragments into * one row per run and measures nothing. */ export async function measured(what: string, bound: number, task: (ms: number) => Promise): Promise { const startedAt = Date.now(); let ok = false; try { const out = await task(bound); ok = true; return out; } finally { record(what, Date.now() - startedAt, ok, bound); } } /** Whether the caller asked for the table. */ export function timingsWanted(): boolean { return (process.env.E2E_TIMINGS ?? "") !== ""; } function fmt(ms: number): string { return ms >= 10_000 ? `${(ms / 1000).toFixed(0)}s` : `${(ms / 1000).toFixed(1)}s`; } /** * Print what was measured: per operation, the healthy observations and the headroom its * bound has over the SLOWEST of them. * * Failed attempts are counted but excluded from the statistics, because an operation that * hit its bound measures the bound and not the operation — feeding that back into the sizing * is how a bound ratchets upward for ever, one bad run at a time. */ export function printTimings(): void { if (samples.size === 0) { console.log("\n── measured durations ── nothing was recorded."); return; } const rows = [...samples.entries()].map(([what, all]) => { const good = all.filter((s) => s.ok).map((s) => s.ms).sort((a, b) => a - b); const bound = all[all.length - 1]!.bound; const failed = all.length - good.length; return { what, n: good.length, min: good.length === 0 ? null : good[0]!, max: good.length === 0 ? null : good[good.length - 1]!, bound, failed, }; }); const width = Math.max(...rows.map((r) => r.what.length), 9); console.log("\n── measured durations (E2E_TIMINGS) ─────────────────────────────────────────"); console.log( ` ${"operation".padEnd(width)} ${"n".padStart(3)} ${"min".padStart(6)} ${"max".padStart(6)}` + ` ${"bound".padStart(6)} headroom failed`, ); for (const r of rows) { const headroom = r.max === null || r.max === 0 ? "—" : `${(r.bound / r.max).toFixed(0)}x`; console.log( ` ${r.what.padEnd(width)} ${String(r.n).padStart(3)} ` + `${(r.min === null ? "—" : fmt(r.min)).padStart(6)} ${(r.max === null ? "—" : fmt(r.max)).padStart(6)} ` + `${fmt(r.bound).padStart(6)} ${headroom.padStart(8)} ${r.failed === 0 ? "" : String(r.failed)}`, ); } console.log( " (statistics are over SUCCESSFUL attempts only: a wait that hit its bound measures\n" + " the bound, and sizing the next bound from it ratchets upward for ever.)", ); }