From 8af8b0738a41fc562cb70f227684cc67e94db3c2 Mon Sep 17 00:00:00 2001 From: thelastbackspace <23155651+thelastbackspace@users.noreply.github.com> Date: Fri, 6 Nov 2026 15:20:25 +0100 Subject: [PATCH] feat: link each finding to its evidence on the HTML report's flame chart --- CHANGELOG.md | 1 + README.md | 2 +- src/__tests__/cli.test.ts | 19 ++++++++++++ src/__tests__/explain-auto-profile.test.ts | 13 +++++++++ src/__tests__/run.test.ts | 2 +- src/cli.ts | 24 +++++++++++---- src/core/explain.ts | 34 +++++++++++++++++++--- src/report-html.ts | 33 +++++++++++++++++++-- src/run.ts | 2 +- 9 files changed, 116 insertions(+), 14 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 9266a8f..49e1f1d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added - **`traceperf run`:** starts an app with `traceperf/auto`, sends concurrent traffic (`--path`, `-c`, `-d`/`-n`, `--method`; warm-up requests first), then prints statistics and explanations. Without `--path`, use the app yourself and press Ctrl-C. Works with a script (`traceperf run server.js`) or any command (`traceperf run -- npm start`). `--html`, `--output`, `--json`. +- **Evidence links in the HTML report:** the report now opens with the findings ("Why it was slow"); click one to highlight its time range on the flame chart (no scripts, works from disk). Each finding carries `evidence: { start, end, labels }` in `explain()` and `--json` output. - **Known-slow example apps** (`examples/slow-apps/`): one planted cause each; a test checks that `explain` names it. - **Blocking code is named even when untracked:** `traceperf run` (and `TRACEPERF_PROFILE_BLOCKING=1` with `traceperf/auto`) samples the CPU during the synchronous part of blocking calls, and `explain` names the function and line (`CPU time: buildReport (server.js:10) 100%`). Native work is named by the calling app function (`hashPassword → pbkdf2Sync`), code V8 inlined into its caller is credited to the inlined function, and garbage-collection pauses are reported as such. - `traceperf run` reports **queueing the app can't see**: clients' latency compared with the app's own timings, per path. diff --git a/README.md b/README.md index 6c23193..fd5bad0 100644 --- a/README.md +++ b/README.md @@ -584,7 +584,7 @@ render 1.886 1.966 +4.2% unchanged ### Reports and live view ```bash -npx traceperf report trace.json --html report.html # one self-contained file: flame chart, stats, slowest calls +npx traceperf report trace.json --html report.html # one self-contained file: findings linked to the flame chart, stats, slowest calls npx traceperf watch calls.jsonl # live top-style view while the app writes the log ``` diff --git a/src/__tests__/cli.test.ts b/src/__tests__/cli.test.ts index f8f3dc0..31a3240 100644 --- a/src/__tests__/cli.test.ts +++ b/src/__tests__/cli.test.ts @@ -95,6 +95,25 @@ test('--html writes a self-contained report with one bar per call', async () => } }); +test('the HTML report lists findings, each linked to its time range on the chart', async () => { + const { trace, jsonl } = await sample(); + for (const input of [trace, jsonl]) { + const html = report(input, { html: true }); + expect(html).toContain('Why it was slow'); + // the failing cache.get is a finding with evidence: link and band share an id + const link = html.match(/✖ cache\.get in GET \/users failed/); + expect(link).not.toBeNull(); + expect(html).toContain(`' }] }); + expect(html).toContain('
  • ● given <finding>
    • '); + expect(html).not.toContain('class="ev"'); + expect(report(jsonl, { html: true, findings: [] })).not.toContain('Why it was slow'); +}); + function runLog(durations: Record): string { // Synthetic JSON lines: one root per call return Object.entries(durations).flatMap(([label, ds]) => ds.map(d => JSON.stringify({ diff --git a/src/__tests__/explain-auto-profile.test.ts b/src/__tests__/explain-auto-profile.test.ts index b52e5b4..2a6fd4b 100644 --- a/src/__tests__/explain-auto-profile.test.ts +++ b/src/__tests__/explain-auto-profile.test.ts @@ -45,6 +45,19 @@ describe('explain()', () => { expect(findings.filter(f => f.kind === 'blocked').map(f => f.root)).toEqual(['req2']); }); + test('each finding points at the time range and calls that show it', () => { + const cpu = node('cpu', 50, 30, { async: false, syncDuration: 30 }); + const req1 = node('req1', 0, 100, { children: [node('db', 0, 50), cpu], selfDuration: 20 }); + const req2 = node('req2', 10, 100, { children: [node('db', 10, 80)], selfDuration: 20 }); + const findings = explain([req1, req2]); + expect(findings.find(f => f.kind === 'blocking')!.evidence).toEqual({ start: 50, end: 80, labels: ['cpu'] }); + expect(findings.find(f => f.kind === 'blocked')!.evidence).toEqual({ start: 10, end: 110, labels: ['req2', 'cpu'] }); + const seq = node('page', 0, 30, { children: [node('a', 0, 10), node('b', 10, 10), node('c', 20, 10)] }); + expect(explain([seq]).find(f => f.kind === 'sequential')!.evidence).toEqual({ start: 0, end: 30, labels: ['a', 'b', 'c'] }); + const n1 = node('list', 0, 60, { children: Array.from({ length: 6 }, (_, i) => node('q', 5 + i * 9, 9)) }); + expect(explain([n1]).find(f => f.kind === 'repeated')!.evidence).toEqual({ start: 5, end: 59, labels: ['q'] }); + }); + test('blocking is attributed to the deepest call that did it', () => { const inner = node('parseJson', 0, 40, { async: false, syncDuration: 40 }); const outer = node('handler', 0, 42, { async: false, syncDuration: 42, children: [inner] }); diff --git a/src/__tests__/run.test.ts b/src/__tests__/run.test.ts index 6222f21..10787a1 100644 --- a/src/__tests__/run.test.ts +++ b/src/__tests__/run.test.ts @@ -146,7 +146,7 @@ describe('runApp', () => { expect(text).toContain('load: 20 requests'); expect(text).toContain('Why it was slow:'); expect(text).toContain('Promise.all'); - expect(fs.readFileSync(html, 'utf8')).toContain(' + typeof node.startMs === 'number' ? node.startMs : typeof node.start === 'string' ? Date.parse(node.start) : 0; + /** Parse a Chrome trace or JSON-lines document into flat calls */ export function parseCalls(text: string): Call[] { const trimmed = text.trim(); @@ -88,7 +94,7 @@ export function parseCalls(text: string): Call[] { const laneEnds: number[] = []; const visit = (node: any, parents: string[], lane: number) => { const path = [...parents, node.label].join(' > '); - const start = typeof node.start === 'string' ? Date.parse(node.start) : 0; + const start = startOf(node); calls.push({ label: node.label, path, @@ -122,7 +128,7 @@ export function parseCalls(text: string): Call[] { if (typeof node.label !== 'string' || typeof node.durationMs !== 'number') { throw new Error(`line ${i + 1} is not a traceperf record`); } - const start = typeof node.start === 'string' ? Date.parse(node.start) : 0; + const start = startOf(node); visit(node, [], pickLane(start, start + node.durationMs)); }); return calls; @@ -166,7 +172,7 @@ export function parseTrees(text: string): ExplainNode[] { } const convert = (n: any): ExplainNode => ({ label: n.label, - startTime: typeof n.startMs === 'number' ? n.startMs : typeof n.start === 'string' ? Date.parse(n.start) : 0, + startTime: startOf(n), duration: n.durationMs, selfDuration: typeof n.selfMs === 'number' ? n.selfMs : n.durationMs, syncDuration: typeof n.syncMs === 'number' ? n.syncMs : undefined, @@ -233,7 +239,15 @@ export function report(text: string, options: ReportOptions = {}): string { const slowest = calls.slice().sort((a, b) => b.duration - a.duration).slice(0, top); if (options.html) { - return renderHtmlReport(calls, stats, { title: options.title, top: options.top ?? 20 }); + let findings = options.findings; + if (!findings) { + try { + findings = explain(parseTrees(text), { max: 10 }); + } catch { + findings = []; + } + } + return renderHtmlReport(calls, stats, { title: options.title, top: options.top ?? 20, findings }); } if (options.json) { return JSON.stringify({ calls: calls.length, stats, slowest }, null, 2); diff --git a/src/core/explain.ts b/src/core/explain.ts index 7887229..b0d4dc0 100644 --- a/src/core/explain.ts +++ b/src/core/explain.ts @@ -35,8 +35,22 @@ export interface Finding { ms: number; /** For blocking / blocked: the call whose synchronous code blocked */ call?: string; + /** Where to look: the time range (same clock as the input) and the calls involved */ + evidence?: FindingEvidence; } +export interface FindingEvidence { + start: number; + end: number; + labels: string[]; +} + +const span = (nodes: ExplainNode[], labels: string[]): FindingEvidence => ({ + start: Math.min(...nodes.map(n => n.startTime)), + end: Math.max(...nodes.map(n => n.startTime + n.duration)), + labels: [...new Set(labels)], +}); + /** Where a blocking call spent its CPU time (from the sampling profiler) */ export interface BlockingHotspot { functionName: string; @@ -142,18 +156,19 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin const rootEnd = root.startTime + root.duration; // 1. Delayed by blocking code in other top-level calls - const byLabel = new Map }>(); + const byLabel = new Map; ranges: Blocker[] }>(); for (const b of blockers) { if (b.root === i) continue; const ms = overlap(root.startTime, rootEnd, b.start, b.end); if (ms <= 0) continue; - const entry = byLabel.get(b.label) ?? { ms: 0, roots: new Set() }; + const entry = byLabel.get(b.label) ?? { ms: 0, roots: new Set(), ranges: [] }; entry.ms += ms; + entry.ranges.push(b); entry.roots.add(roots[b.root].label); byLabel.set(b.label, entry); } let blockedTotal = 0; - byLabel.forEach(({ ms, roots: from }, label) => { + byLabel.forEach(({ ms, roots: from, ranges }, label) => { blockedTotal += ms; if (ms < minMs) return; const others = [...from].filter(r => r !== label); @@ -164,6 +179,11 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin root: rootLabel, ms, call: label, + evidence: { + start: Math.min(root.startTime, ...ranges.map(r => r.start)), + end: Math.max(rootEnd, ...ranges.map(r => r.end)), + labels: [rootLabel, label], + }, message: `${rootLabel} waited ~${fmt(ms)} (${pct(ms, root.duration)} of its ${fmt(root.duration)}) while ${label}${where} blocked the event loop${culprit(label, true)}`, }); }); @@ -178,6 +198,7 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin root: rootLabel, ms, call: b.label, + evidence: { start: b.start, end: b.end, labels: [b.label] }, message: `${b.label} ran ${fmt(ms)} of synchronous code, blocking everything else in the process for that long${culprit(b.label, false)}`, }); } @@ -206,6 +227,7 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin root: rootLabel, ms: saving, group: node.label, + evidence: span(run, run.map(k => k.label)), message: `${node.label} awaited ${run.length} calls one after another (${shown}: ${fmt(total)}); if they are independent, Promise.all could save up to ~${fmt(saving)}`, }); } @@ -237,6 +259,7 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin kind: 'repeated', root: rootLabel, ms, + evidence: span(kids.filter(k => k.label === label), [label]), message: `${node.label} called ${label} ${n} times (${fmt(ms)} total); batching them into one call may help (N+1 pattern)`, }); } @@ -256,6 +279,7 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin kind: 'dominant', root: rootLabel, ms: k.duration - waited, + evidence: span([k], [k.label]), message: `${k.label} took ${pct(k.duration, root.duration)} of ${rootLabel} (${fmt(k.duration)} of ${fmt(root.duration)})${note}`, }); } @@ -267,6 +291,7 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin kind: 'dominant', root: rootLabel, ms: own, + evidence: span([root], [rootLabel]), message: `${pct(own, root.duration)} of ${rootLabel} (${fmt(own)}) is outside any tracked call; track the code inside it to see where`, }); } @@ -281,6 +306,7 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin kind: 'error', root: rootLabel, ms: node.duration, + evidence: span([node], [node.label]), message: `${node === root ? node.label : `${node.label} in ${rootLabel}`} failed after ${fmt(node.duration)}: ${msg}`, }); }); @@ -298,7 +324,7 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin else { g.times++; g.roots.add(f.root); - if (f.ms > g.ms) Object.assign(g, { ms: f.ms, message: f.message }); + if (f.ms > g.ms) Object.assign(g, { ms: f.ms, message: f.message, evidence: f.evidence }); } } const order: Record = { error: 0, blocked: 1, blocking: 2, repeated: 3, sequential: 4, dominant: 5 }; diff --git a/src/report-html.ts b/src/report-html.ts index 10316a5..b6e126e 100644 --- a/src/report-html.ts +++ b/src/report-html.ts @@ -5,6 +5,9 @@ */ import type { Call } from './cli'; import type { LabelStats } from './core/stats'; +import type { Finding } from './core/explain'; + +const ICON: Record = { error: '✖', blocked: '⏳', blocking: '🔥', repeated: '🔁', sequential: '⇉', dominant: '●', queued: '⏳' }; const esc = (s: unknown): string => String(s) .replace(/&/g, '&').replace(//g, '>').replace(/"/g, '"'); @@ -20,7 +23,7 @@ function colorFor(label: string, failed: boolean): string { const ms = (n: number): string => (n >= 1000 ? `${(n / 1000).toFixed(2)} s` : `${n.toFixed(n < 10 ? 3 : 1)} ms`); -export function renderHtmlReport(calls: Call[], stats: Record, options: { title?: string; top?: number } = {}): string { +export function renderHtmlReport(calls: Call[], stats: Record, options: { title?: string; top?: number; findings?: Finding[] } = {}): string { const title = options.title ?? 'traceperf report'; const top = options.top ?? 20; const width = 1200; @@ -55,6 +58,26 @@ export function renderHtmlReport(calls: Call[], stats: Record${esc(tip)}${text}`; }).join('\n'); + // Findings: each links to a band over the chart showing its time range + const findings = options.findings || []; + const clampX = (t: number) => Math.min(width, Math.max(0, x(t))); + const bands = findings.map((f, i) => { + const ev = f.evidence; + if (!ev || !calls.length || ev.end < start || ev.start > end) return ''; + const bx = clampX(ev.start); + const bw = Math.max(3, clampX(ev.end) - bx); + return `${esc(`${ev.labels.join(', ')}\n${ms(ev.end - ev.start)}`)}`; + }); + const findingItems = findings.map((f, i) => { + const text = `${ICON[f.kind] || '•'} ${esc(f.message)}`; + return bands[i] + ? `
  • ${text} at ${esc(ms(f.evidence!.start - start))}, ${esc(f.evidence!.labels.slice(0, 3).join(', '))}
    • ` + : `
  • ${text}
    • `; + }).join('\n'); + const findingsSection = findings.length + ? `

    Why it was slow

    \n
      \n${findingItems}\n
    \n

    Click a finding to highlight its time range on the flame chart.

    ` + : ''; + const ticks = Array.from({ length: 6 }, (_, i) => { const tx = (i / 5) * width; return `${esc(ms((span * i) / 5))}`; @@ -92,16 +115,22 @@ export function renderHtmlReport(calls: Call[], stats: Record

    ${esc(title)}

    ${calls.length} calls · ${Object.keys(stats).length} labels · ${lanes.length} lane${lanes.length === 1 ? '' : 's'} · span ${esc(ms(span))}. Hover a bar for details.

    -

    Flame chart

    +${findingsSection} +

    Flame chart

    ${ticks} ${rects} +${bands.join('\n')}

    Statistics (ms)

    diff --git a/src/run.ts b/src/run.ts index 9b6849c..8f5e39d 100644 --- a/src/run.ts +++ b/src/run.ts @@ -351,7 +351,7 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise { summary.findings.splice(after, 0, ...queued); } if (args.html && summary.trees) { - fs.writeFileSync(args.html, deps.report(text, { html: true, title: `traceperf run: ${args.command.join(' ')}` })); + 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));
    labelcallserrorstotalmeanp50p95p99maxself mean