diff --git a/CHANGELOG.md b/CHANGELOG.md index 5440056..c43bd91 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,9 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added +- **A PR check that isn't flaky:** `traceperf run --save-baseline perf-baseline.json` records how many calls of each kind every route makes per request; `--baseline perf-baseline.json` compares and exits 1 when a route makes more (`GET /orders: pg SELECT items 1 → 12 per request (an N+1?)`) or a new N+1 / error appears. Counts, not timings, so the result is the same on any machine. + ### Added - **Fastify route labels:** with `traceperf/auto` or `traceperf run`, Fastify (3–5) requests are labelled by route, `GET /api/articles/:slug`, instead of one label per URL. `traceperf/auto` wraps the `fastify()` factory to add an `onRequest` hook (`wrapFastifyFactory` for doing it by hand). Any framework can do the same by setting the `ROUTE` symbol on the raw request. - **Koa route labels:** with `@koa/router` or `koa-router`, Koa requests are labelled by the matched route (`GET /api/users/:id`), auto-detected; `labelKoaRoutes(require('koa'))` by hand. diff --git a/README.md b/README.md index 5ddd663..7dd8d39 100644 --- a/README.md +++ b/README.md @@ -106,6 +106,30 @@ Checked on real apps, not only on the planted ones: Prisma's REST example, the R - `--no-profile`: don't sample the CPU. - Any start command works: `npx traceperf run -- npm start`. +### In CI: fail a PR that adds queries + +Timings are too noisy to gate a PR on (the same run can be twice as fast on an idle machine), but how many queries a route makes per request is exact. Save a baseline once, commit it, and compare on every PR: + + +```bash +npx traceperf run server.js --path /orders --path /users/1 --save-baseline perf-baseline.json +npx traceperf run server.js --path /orders --path /users/1 --baseline perf-baseline.json # exit 1 on regressions +``` + +``` +Compared with perf-baseline.json: + ✖ GET /orders: pg SELECT items 1 → 12 per request (an N+1?) + ✖ new problem: N+1 in GET /orders +``` + +It fails when a route makes more calls of any kind per request (database queries, HTTP calls, Redis commands) or an N+1 or error appears; fewer calls are reported as improvements. Counts come from the one-at-a-time requests, so they don't depend on the machine. In GitHub Actions, with a service container for the database: + + +```yaml +- run: npm ci && npm run db:seed +- run: npx traceperf run dist/server.js --path /orders --path /users/1 --baseline perf-baseline.json +``` + `examples/slow-apps/` has small apps with one planted problem each (blocking in your code, blocking in built-ins, sequential awaits, N+1, a slow dependency, errors); CI checks that `run` names each one. The same naming works without `run`: `TRACEPERF_PROFILE_BLOCKING=1 node --require traceperf/auto server.js` adds the function names to the exit summary (sampling costs a few percent CPU, so use it while investigating). In code: `profileSlowCalls({ select: root => blockingRanges(root), mergeInlined: true, onProfile })`, then `explain(roots, { hotspots })`. diff --git a/src/__tests__/run.test.ts b/src/__tests__/run.test.ts index fa1eecb..81c8276 100644 --- a/src/__tests__/run.test.ts +++ b/src/__tests__/run.test.ts @@ -259,6 +259,32 @@ describe('naming blocking code from CPU profiles', () => { }); }); +describe('baselines (calls per request per route)', () => { + const { baselineOf, compareBaseline } = jest.requireActual('../run'); + const n = (label: string, children: any[] = []) => ({ label, children }); + const orders = (items: number) => n('GET /orders', [n('pg SELECT orders'), ...Array.from({ length: items }, () => n('pg SELECT items'))]); + + it('takes the median count of each call per request', () => { + const b = baselineOf([orders(1), orders(1), orders(3), n('GET /health')], []); + expect(b.routes).toEqual({ + 'GET /health': { requests: 1, calls: {} }, + 'GET /orders': { requests: 3, calls: { 'pg SELECT items': 1, 'pg SELECT orders': 1 } }, + }); + const withN1 = baselineOf([orders(12)], [{ kind: 'repeated', root: 'GET /orders', ms: 50, message: '' }, { kind: 'blocking', root: 'GET /x', ms: 20, message: '' }]); + expect(withN1.problems).toEqual(['N+1 in GET /orders']); // blocking is timing, not in the baseline + }); + + it('flags more calls per request and new problems; reports improvements', () => { + const before = baselineOf([orders(1), n('GET /old')], []); + const after = baselineOf([orders(12), n('GET /new')], [{ kind: 'repeated', root: 'GET /orders', ms: 50, message: '' }]); + const r = compareBaseline(before, after); + expect(r.regressions).toEqual(['GET /orders: pg SELECT items 1 → 12 per request (an N+1?)', 'new problem: N+1 in GET /orders']); + expect(r.notes).toEqual(['GET /new: new route (not in the baseline)', 'GET /old: not requested in this run']); + expect(compareBaseline(after, before).improvements).toEqual(['GET /orders: pg SELECT items 12 → 1 per request', 'fixed: N+1 in GET /orders']); + expect(compareBaseline(before, before)).toEqual({ regressions: [], improvements: [], notes: [] }); + }); +}); + describe('statusFinding', () => { const { statusFinding } = jest.requireActual('../run'); const load = (statuses: Record, errors = 0) => ({ requests: 10, errors, statuses, durationMs: 1, latency: {} }); diff --git a/src/run.ts b/src/run.ts index 042ed03..f7bedc2 100644 --- a/src/run.ts +++ b/src/run.ts @@ -34,6 +34,10 @@ export interface RunArgs { /** Request headers, e.g. { authorization: 'Bearer ...' } */ headers?: Record; html?: string; + /** Write call counts per route here (a baseline for --baseline) */ + saveBaseline?: string; + /** Compare call counts per route with this baseline; exit 1 on more calls or new problems */ + baseline?: string; output?: string; json: boolean; max: number; @@ -59,6 +63,10 @@ export const RUN_USAGE = ` traceperf run [app args] [options] --html out.html write an HTML report --output f.jsonl keep the raw request trees --json print stats and findings as JSON + --save-baseline f.json save calls per request for each route (commit it) + --baseline f.json compare with it; exit 1 if a route makes more calls + (e.g. an N+1) or a new problem appears. Counts, not + timings: deterministic, safe for CI --no-profile don't sample the CPU (blocking code is then named only by its tracked call)`; @@ -134,6 +142,8 @@ export function parseRunArgs(argv: string[]): RunArgs | string { break; } case '--json': args.json = true; break; + case '--save-baseline': if (!(args.saveBaseline = argv[++i])) return '--save-baseline expects a file'; break; + case '--baseline': if (!(args.baseline = argv[++i])) return '--baseline expects a file'; break; case '--no-profile': args.profile = false; break; case '--probe': { const n = Number(argv[++i]); @@ -344,6 +354,76 @@ export function statusFinding(load: LoadResult): Finding | undefined { }; } +/** Calls per request for each route, and the kinds of problem found: deterministic, unlike timings */ +export interface Baseline { + version: 1; + routes: Record }>; + /** "kind route" of repeated-call (N+1) and error findings: counts, so deterministic (blocking is timing, so not here) */ + problems: string[]; +} + +interface CountNode { label: string; children: CountNode[] } + +/** Median number of each call label per request, per route */ +export function baselineOf(trees: CountNode[], findings: Finding[]): Baseline { + const byRoute = new Map>>(); + for (const tree of trees) { + const counts = new Map(); + const walk = (n: CountNode) => n.children.forEach(c => { + counts.set(c.label, (counts.get(c.label) || 0) + 1); + walk(c); + }); + walk(tree); + const list = byRoute.get(tree.label) ?? []; + list.push(counts); + byRoute.set(tree.label, list); + } + const routes: Baseline['routes'] = {}; + [...byRoute.keys()].sort().forEach(route => { + const list = byRoute.get(route)!; + const labels = [...new Set(list.flatMap(m => [...m.keys()]))].sort(); + const calls: Record = {}; + for (const label of labels) { + const values = list.map(m => m.get(label) || 0).sort((a, b) => a - b); + const median = values[Math.floor((values.length - 1) / 2)]; + if (median > 0) calls[label] = median; + } + routes[route] = { requests: list.length, calls }; + }); + const problems = [...new Set(findings + .filter(f => (f.kind === 'repeated' || f.kind === 'error') && f.root !== 'load') + .map(f => `${f.kind === 'repeated' ? 'N+1' : 'errors'} in ${f.root}`))].sort(); + return { version: 1, routes, problems }; +} + +/** Differences that make a PR worse: more calls per request on a route, or a new problem */ +export function compareBaseline(before: Baseline, now: Baseline): { regressions: string[]; improvements: string[]; notes: string[] } { + const regressions: string[] = []; + const improvements: string[] = []; + const notes: string[] = []; + for (const route of Object.keys(now.routes).sort()) { + const b = before.routes[route]; + const a = now.routes[route]; + if (!b) { + notes.push(`${route}: new route (not in the baseline)`); + continue; + } + const labels = [...new Set([...Object.keys(b.calls), ...Object.keys(a.calls)])].sort(); + for (const label of labels) { + const x = b.calls[label] || 0; + const y = a.calls[label] || 0; + if (y > x) regressions.push(`${route}: ${label} ${x} → ${y} per request${x <= 1 && y >= 5 ? ' (an N+1?)' : ''}`); + else if (y < x) improvements.push(`${route}: ${label} ${x} → ${y} per request`); + } + } + for (const route of Object.keys(before.routes)) { + if (!now.routes[route]) notes.push(`${route}: not requested in this run`); + } + for (const p of now.problems) if (!before.problems.includes(p)) regressions.push(`new problem: ${p}`); + for (const p of before.problems) if (!now.problems.includes(p)) improvements.push(`fixed: ${p}`); + return { regressions, improvements, notes }; +} + export interface RunSummary { stats: string; findings: Finding[]; @@ -584,11 +664,25 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise { const after = summary.findings.filter(f => f.kind === 'error' || f.kind === 'blocking').length; summary.findings.splice(after, 0, ...queued); } + // Baselines use the one-at-a-time probe when there is one (the same requests every run) + let baselineReport: { regressions: string[]; improvements: string[]; notes: string[] } | undefined; + let baselineError: string | undefined; + if ((args.saveBaseline || args.baseline) && summary.trees) { + const current = baselineOf(deps.parseTrees(probeText.trim() ? probeText : text), summary.findings); + if (args.saveBaseline) fs.writeFileSync(args.saveBaseline, JSON.stringify(current, null, 2) + '\n'); + if (args.baseline) { + try { + baselineReport = compareBaseline(JSON.parse(fs.readFileSync(args.baseline, 'utf8')), current); + } catch (e) { + baselineError = `traceperf: could not read the baseline ${args.baseline}: ${e instanceof Error ? e.message : String(e)}`; + } + } + } if (args.html && summary.trees) { fs.writeFileSync(args.html, deps.report(text, { html: true, findings: summary.findings, title: `traceperf run: ${args.command.join(' ')}` })); } if (args.json) { - deps.out(JSON.stringify({ load, trees: summary.trees, findings: summary.findings }, null, 2)); + deps.out(JSON.stringify({ load, trees: summary.trees, findings: summary.findings, ...(baselineReport ? { baseline: baselineReport } : {}) }, null, 2)); } else if (!summary.trees) { deps.out('\ntraceperf: no requests were tracked.'); } else { @@ -600,10 +694,21 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise { lines.push('', summary.stats, '', 'Why it was slow:', formatFindings(summary.findings)); if (args.html) lines.push('', `HTML report: ${args.html}`); if (args.output) lines.push(`Request trees: ${args.output}`); + if (args.saveBaseline) lines.push(`Baseline saved: ${args.saveBaseline}`); + if (baselineReport) { + const { regressions, improvements, notes } = baselineReport; + lines.push('', `Compared with ${args.baseline}:`); + regressions.forEach(r => lines.push(` ✖ ${r}`)); + improvements.forEach(r => lines.push(` ✔ ${r}`)); + notes.forEach(r => lines.push(` · ${r}`)); + if (!regressions.length && !improvements.length) lines.push(' ✔ same calls per request on every route'); + } deps.out(lines.join('\n')); } + if (baselineError) deps.err(baselineError); if (!args.output) fs.rmSync(dir, { recursive: true, force: true }); // Interactive runs end with Ctrl-C; that is success. A crash before any traffic is not. + if (baselineError || (baselineReport && baselineReport.regressions.length)) return 1; return !summary.trees && exitCode ? 1 : 0; }