From 6400ca8f53247a652ba421512e7abee9a48e5f97 Mon Sep 17 00:00:00 2001 From: thelastbackspace <23155651+thelastbackspace@users.noreply.github.com> Date: Fri, 6 Nov 2026 20:42:08 +0100 Subject: [PATCH] feat(run): per-request findings from a one-at-a-time probe; call out failed responses --- CHANGELOG.md | 7 ++ src/__tests__/explain-auto-profile.test.ts | 9 ++- src/__tests__/run.test.ts | 17 ++++- src/core/explain.ts | 5 +- src/run.ts | 89 ++++++++++++++++++---- 5 files changed, 108 insertions(+), 19 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3039c6f..27169f9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,13 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added +- **`traceperf run` measures in two phases.** After the warm-up it sends `--probe` requests per path (default 10) one at a time, then the concurrent load. Per-request findings (a dominant call, sequential awaits, N+1) come from the one-at-a-time phase: under load every await also waits for the busy event loop, so a 1 ms query on a 60-row table measured 12 ms and was reported as "check this query's plan". Blocking, queueing, errors and CPU cost still come from the load. +- **Failed responses are called out first:** "2117 of 2117 responses failed (most: 2117× 401 Unauthorized), so the timings below describe error responses", with a hint (`-H` for 401/403, `--path` for 404). An expired token used to give "no issues found". + +### Changed (from running it on a NestJS 7 + TypeORM app) +- A finding seen once in 10 or more requests is an outlier, not a pattern (was: only under 5% of 20+). + ## [1.6.0] - 2026-11-06 (Includes 1.5.1, which was tagged but never published.) diff --git a/src/__tests__/explain-auto-profile.test.ts b/src/__tests__/explain-auto-profile.test.ts index 6629626..96b7469 100644 --- a/src/__tests__/explain-auto-profile.test.ts +++ b/src/__tests__/explain-auto-profile.test.ts @@ -142,10 +142,13 @@ describe('explain()', () => { // A request that makes one call is always mostly that call: not worth saying unless it is slow expect(explain([node('GET /a', 0, 21, { selfDuration: 1, children: [node('db', 0, 20)] })])).toEqual([]); expect(explain([node('GET /a', 0, 151, { selfDuration: 1, children: [node('db', 0, 150)] })])[0].kind).toBe('dominant'); - // 9 requests where the query is 4 ms of 5 ms, one where the first connection made it 110 ms - const roots = [110, ...Array(9).fill(4)].map(ms => node('GET /users', 0, ms + 1, { selfDuration: 0.5, children: [node('db', 0, ms), node('auth', ms, 0.5)] })); + // 7 requests where the query is 4 ms of 5 ms, one where the first connection made it 110 ms + const roots = [110, ...Array(7).fill(4)].map(ms => node('GET /users', 0, ms + 1, { selfDuration: 0.5, children: [node('db', 0, ms), node('auth', ms, 0.5)] })); const [once] = explain(roots).filter(f => f.kind === 'dominant'); - expect(once.message).toMatch(/\(in 1 of 10 GET \/users\)$/); + expect(once.message).toMatch(/\(in 1 of 8 GET \/users\)$/); + // once in 10 or more is an outlier + const ten = [110, ...Array(9).fill(4)].map(ms => node('GET /users', 0, ms + 1, { selfDuration: 0.5, children: [node('db', 0, ms), node('auth', ms, 0.5)] })); + expect(explain(ten).filter(f => f.kind === 'dominant')).toEqual([]); // ... and once in 40 requests is noise const many = [110, ...Array(39).fill(4)].map(ms => node('GET /users', 0, ms + 1, { selfDuration: 0.5, children: [node('db', 0, ms), node('auth', ms, 0.5)] })); expect(explain(many).filter(f => f.kind === 'dominant')).toEqual([]); diff --git a/src/__tests__/run.test.ts b/src/__tests__/run.test.ts index d24892f..254292e 100644 --- a/src/__tests__/run.test.ts +++ b/src/__tests__/run.test.ts @@ -159,7 +159,7 @@ describe('runApp', () => { const html = path.join(dir, 'r.html'); const output = path.join(dir, 'calls.jsonl'); const out: string[] = []; - const args = parseRunArgs([path.join(APPS, 'sequential', 'server.js'), '--path', '/dashboard', '-n', '20', '--html', html, '--output', output, '--warmup', '0']) as RunArgs; + const args = parseRunArgs([path.join(APPS, 'sequential', 'server.js'), '--path', '/dashboard', '-n', '20', '--html', html, '--output', output, '--warmup', '0', '--probe', '0']) as RunArgs; expect(await runApp(args, deps(out))).toBe(0); const text = out.join('\n'); expect(text).toContain('load: 20 requests'); @@ -259,6 +259,21 @@ describe('naming blocking code from CPU profiles', () => { }); }); +describe('statusFinding', () => { + const { statusFinding } = jest.requireActual('../run'); + const load = (statuses: Record, errors = 0) => ({ requests: 10, errors, statuses, durationMs: 1, latency: {} }); + it('warns when most responses failed, with a hint for the status', () => { + const f = statusFinding(load({ 401: 9, 200: 1 })); + expect(f.message).toBe('9 of 10 responses failed (most: 9× 401 Unauthorized), so the timings below describe error responses, not the endpoints'); + expect(f.fix).toMatch(/-H "Authorization: Bearer \$TOKEN"/); + expect(statusFinding(load({ 404: 6, 200: 4 })).fix).toMatch(/--path/); + expect(statusFinding(load({}, 5)).message).toMatch(/most: 5× connection error/); + }); + it('says nothing when most succeeded', () => { + expect(statusFinding(load({ 200: 8, 500: 2 }))).toBeUndefined(); + }); +}); + describe('busyFinding', () => { const { busyFinding } = jest.requireActual('../run'); const load = { requests: 400, errors: 0, statuses: {}, durationMs: 4000, latency: {} }; diff --git a/src/core/explain.ts b/src/core/explain.ts index 0b347ce..e78fa98 100644 --- a/src/core/explain.ts +++ b/src/core/explain.ts @@ -380,7 +380,10 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin const total = rootCount.get(g.root) || 0; // Blocking counts per root label too; a rare but long block (a 2 s export) is still worth saying const scope = g.kind === 'blocking' ? Math.max(...[...g.roots].map(r => rootCount.get(r) || 0)) : total; - const rare = (g.roots.size === 1 || g.kind === 'blocking') && scope >= 20 && g.times / scope < 0.05 && !((g.kind === 'blocking' || g.kind === 'blocked') && g.ms >= 100); + // Under 5% of 20+ requests, or once in 10+: an outlier, not a pattern + const rare = (g.roots.size === 1 || g.kind === 'blocking') && + ((scope >= 20 && g.times / scope < 0.05) || (scope >= 10 && g.times === 1)) && + !((g.kind === 'blocking' || g.kind === 'blocked') && g.ms >= 100); if (g.ms < minMs || rare) grouped.delete(key); else if (g.kind !== 'blocking' && g.roots.size === 1 && total > g.times) share.set(g, `in ${g.times} of ${total} ${g.root}`); } diff --git a/src/run.ts b/src/run.ts index b061b40..059b7e3 100644 --- a/src/run.ts +++ b/src/run.ts @@ -21,6 +21,13 @@ export interface RunArgs { requests?: number; /** Requests per path sent before measuring (not reported), default 3 */ warmup: number; + /** + * Requests per path sent one at a time after the warm-up (default 10, 0 + * for none). Per-request findings (a dominant call, sequential awaits, + * N+1) come from these: under concurrent load every await also waits for + * the busy event loop, which inflates call times. + */ + probe: number; port?: number; host: string; method: string; @@ -47,6 +54,8 @@ export const RUN_USAGE = ` traceperf run [app args] [options] --method GET request method -H, --header "Name: value" request header, repeatable (e.g. -H "Authorization: Bearer $TOKEN") --warmup 3 untimed requests per path first (cold start), 0 for none + --probe 10 requests per path sent one at a time before the load, for + per-request findings with undistorted timings (0: none) --html out.html write an HTML report --output f.jsonl keep the raw request trees --json print stats and findings as JSON @@ -64,7 +73,7 @@ function parseDuration(value: string | undefined): number | undefined { export function parseRunArgs(argv: string[]): RunArgs | string { const args: RunArgs = { command: [], paths: [], concurrency: 10, durationMs: 5000, host: '127.0.0.1', - method: 'GET', warmup: 3, json: false, profile: true, max: 10, startTimeoutMs: 15000, + method: 'GET', warmup: 3, probe: 10, json: false, profile: true, max: 10, startTimeoutMs: 15000, }; const num = (name: string, v: string | undefined): number | string => { const n = Number(v); @@ -126,6 +135,12 @@ export function parseRunArgs(argv: string[]): RunArgs | string { } case '--json': args.json = true; break; case '--no-profile': args.profile = false; break; + case '--probe': { + const n = Number(argv[++i]); + if (!(n >= 0)) return '--probe expects a number'; + args.probe = Math.floor(n); + break; + } default: // Our options can come before or after the app; anything else after // the app is the app's own argument (use -- to pass everything as is) @@ -281,6 +296,31 @@ export function busyFinding(samples: LoadSample[], load: LoadResult, window: { s }; } +const STATUS_TEXT: Record = { + 400: 'Bad Request', 401: 'Unauthorized', 403: 'Forbidden', 404: 'Not Found', 405: 'Method Not Allowed', + 429: 'Too Many Requests', 500: 'Internal Server Error', 502: 'Bad Gateway', 503: 'Service Unavailable', +}; + +/** Most responses were errors: the timings describe error handling, not the endpoint */ +export function statusFinding(load: LoadResult): Finding | undefined { + const total = Object.values(load.statuses).reduce((a, b) => a + b, 0) + load.errors; + const failed = Object.entries(load.statuses).filter(([s]) => Number(s) >= 400); + const failedCount = failed.reduce((sum, [, n]) => sum + n, 0) + load.errors; + if (total === 0 || failedCount < 0.5 * total) return undefined; + const [top, n] = failed.sort((a, b) => b[1] - a[1])[0] || ['connection error', load.errors]; + const what = /^\d+$/.test(top) ? `${top}${STATUS_TEXT[top] ? ` ${STATUS_TEXT[top]}` : ''}` : top; + const hint = top === '401' || top === '403' + ? 'pass credentials with -H, e.g. -H "Authorization: Bearer $TOKEN" (an expired token gives this too)' + : top === '404' ? 'check the --path values' : 'look at the app output above for the error'; + return { + kind: 'error', + root: 'load', + ms: 0, + message: `${failedCount} of ${total} responses failed (most: ${n}× ${what}), so the timings below describe error responses, not the endpoints`, + fix: hint, + }; +} + export interface RunSummary { stats: string; findings: Finding[]; @@ -406,6 +446,16 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise { let load: LoadResult | undefined; let skipBytes = 0; + let probeFrom: number | undefined; + const sizeNow = async (): Promise => { + // The last trees are written just after their responses + await new Promise(r => setTimeout(r, 100)); + try { + return fs.statSync(output).size; + } catch { + return 0; + } + }; try { if (args.paths.length) { const port = args.port ?? (await waitForPort(fs, readyFile, () => exited, args.startTimeoutMs)); @@ -419,13 +469,13 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise { deps.err(`traceperf: sending ${args.requests ? `${args.requests} requests` : `${args.durationMs / 1000} s of traffic`} to ${args.paths.join(', ')} on port ${port}, ${args.concurrency} at a time`); if (args.warmup > 0) { await sendLoad(deps.http, { ...args, concurrency: 1, requests: args.warmup * args.paths.length }, port); - // The last warm-up trees are written just after their responses - await new Promise(r => setTimeout(r, 100)); - try { - skipBytes = fs.statSync(output).size; - } catch { - skipBytes = 0; - } + skipBytes = await sizeNow(); + } + // One at a time: timings not inflated by queueing (only useful when the load is concurrent) + if (args.probe > 0 && args.concurrency > 1) { + probeFrom = skipBytes; + await sendLoad(deps.http, { ...args, concurrency: 1, requests: args.probe * args.paths.length }, port); + skipBytes = await sizeNow(); } const loadStart = Date.now(); load = await sendLoad(deps.http, args, port); @@ -445,15 +495,18 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise { } let text = ''; + let probeText = ''; try { const all = fs.readFileSync(output); - // If the cut fell inside a tree still being written, start at the next whole line - let from = skipBytes; - if (from > 0 && from < all.length && all[from - 1] !== 0x0a) { - const nl = all.indexOf(0x0a, from); - from = nl === -1 ? all.length : nl + 1; - } + // If a cut fell inside a tree still being written, move it to the next whole line + const align = (at: number) => { + if (at <= 0 || at >= all.length || all[at - 1] === 0x0a) return Math.min(Math.max(at, 0), all.length); + const nl = all.indexOf(0x0a, at); + return nl === -1 ? all.length : nl + 1; + }; + const from = align(skipBytes); text = all.subarray(from).toString('utf8'); + if (probeFrom !== undefined) probeText = all.subarray(align(probeFrom), from).toString('utf8'); } catch { text = ''; } @@ -466,7 +519,15 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise { // no profiles: --no-profile, no inspector, or nothing blocked } const summary = summarise(text, deps, args.max, profiles, process.cwd()); + // Per-request structure from the one-at-a-time probe, where call times are not inflated by queueing + const STRUCTURAL = ['dominant', 'sequential', 'repeated']; + if (probeText.trim()) { + const structural = explain(deps.parseTrees(probeText), { max: args.max }).filter(f => STRUCTURAL.includes(f.kind)); + summary.findings = [...summary.findings.filter(f => !STRUCTURAL.includes(f.kind)), ...structural].slice(0, args.max); + } if (load) { + const failing = statusFinding(load); + if (failing) summary.findings.unshift(failing); const blocked = summary.findings.some(f => f.kind === 'blocking'); let queued = queueFindings(load, deps.parseTrees(text), args.method, blocked); let samples: LoadSample[] = [];