Merge pull request #9 from thelastbackspace/feat/evidence-links

Link findings to their evidence in the HTML report

Author: thelastbackspace

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.

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
 ```
 

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(/<a href="#(ev-\d+)">✖ cache\.get in GET \/users failed/);
+    expect(link).not.toBeNull();
+    expect(html).toContain(`<rect id="${link![1]}" class="ev"`);
+    expect(html).toMatch(/rect\.ev:target/);
+    expect(html).not.toMatch(/<script/);
+  }
+  // Findings passed in (as traceperf run does) replace the computed ones; no evidence, no link
+  const html = report(jsonl, { html: true, findings: [{ kind: 'dominant', root: 'x', ms: 1, message: 'given <finding>' }] });
+  expect(html).toContain('<li>● given &lt;finding&gt;</li>');
+  expect(html).not.toContain('class="ev"');
+  expect(report(jsonl, { html: true, findings: [] })).not.toContain('Why it was slow');
+});
+
 function runLog(durations: Record<string, number[]>): string {
   // Synthetic JSON lines: one root per call
   return Object.entries(durations).flatMap(([label, ds]) => ds.map(d => JSON.stringify({

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] });

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('<html');
+    expect(fs.readFileSync(html, 'utf8')).toMatch(/<html[\s\S]*Why it was slow/);
     expect(fs.readFileSync(output, 'utf8').trim().split('\n')).toHaveLength(20);
     fs.rmSync(dir, { recursive: true, force: true });
   }, 30000);

src/cli.ts

@@ -10,7 +10,7 @@
  */
 import { ExecutionRecord } from './core/records';
 import { LabelStats, StatsCollector, formatStatsTable } from './core/stats';
-import { explain, ExplainNode, ExplainOptions, formatFindings } from './core/explain';
+import { explain, ExplainNode, ExplainOptions, Finding, formatFindings } from './core/explain';
 import { renderHtmlReport } from './report-html';
 import { createWatcher, WatchOptions } from './watch';
 import { parseRunArgs, runApp, RUN_USAGE } from './run';
@@ -22,6 +22,8 @@ export interface ReportOptions {
   title?: string;
   sort?: 'total' | 'mean' | 'p95' | 'max' | 'count';
   json?: boolean;
+  /** Findings for the HTML report (default: explain() on the input) */
+  findings?: Finding[];
 }
 
 export interface Call {
@@ -46,6 +48,10 @@ function record(label: string, duration: number, selfDuration: number, error?: s
   };
 }
 
+/** Start in epoch ms: exact startMs when present (ISO strings are rounded to the ms) */
+const startOf = (node: any): number =>
+  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);

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<string, { ms: number; roots: Set<string> }>();
+    const byLabel = new Map<string, { ms: number; roots: Set<string>; 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<string>() };
+      const entry = byLabel.get(b.label) ?? { ms: 0, roots: new Set<string>(), 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<FindingKind, number> = { error: 0, blocked: 1, blocking: 2, repeated: 3, sequential: 4, dominant: 5 };

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<string, string> = { error: '✖', blocked: '⏳', blocking: '🔥', repeated: '🔁', sequential: '⇉', dominant: '●', queued: '⏳' };
 
 const esc = (s: unknown): string => String(s)
   .replace(/&/g, '&amp;').replace(/</g, '&lt;').replace(/>/g, '&gt;').replace(/"/g, '&quot;');
@@ -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<string, LabelStats>, options: { title?: string; top?: number } = {}): string {
+export function renderHtmlReport(calls: Call[], stats: Record<string, LabelStats>, 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<string, LabelStats
     return `<g class="call"><title>${esc(tip)}</title><rect x="${rx.toFixed(1)}" y="${ry}" width="${rw.toFixed(1)}" height="${rowH - 2}" rx="2" fill="${colorFor(c.label, !!c.error)}"/>${text}</g>`;
   }).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 `<rect id="ev-${i}" class="ev" x="${bx.toFixed(1)}" y="${axisH - 4}" width="${bw.toFixed(1)}" height="${height - axisH + 4}"><title>${esc(`${ev.labels.join(', ')}\n${ms(ev.end - ev.start)}`)}</title></rect>`;
+  });
+  const findingItems = findings.map((f, i) => {
+    const text = `${ICON[f.kind] || '•'} ${esc(f.message)}`;
+    return bands[i]
+      ? `<li><a href="#ev-${i}">${text}</a> <span class="at">at ${esc(ms(f.evidence!.start - start))}, ${esc(f.evidence!.labels.slice(0, 3).join(', '))}</span></li>`
+      : `<li>${text}</li>`;
+  }).join('\n');
+  const findingsSection = findings.length
+    ? `<h2>Why it was slow</h2>\n<ol class="findings">\n${findingItems}\n</ol>\n<p class="meta">Click a finding to highlight its time range on the flame chart.</p>`
+    : '';
+
   const ticks = Array.from({ length: 6 }, (_, i) => {
     const tx = (i / 5) * width;
     return `<line x1="${tx}" x2="${tx}" y1="${axisH - 4}" y2="${height}" class="grid"/><text x="${Math.min(tx + 3, width - 60)}" y="14" class="axis">${esc(ms((span * i) / 5))}</text>`;
@@ -92,16 +115,22 @@ export function renderHtmlReport(calls: Call[], stats: Record<string, LabelStats
   th:first-child, td:first-child { text-align: left; } tbody tr:nth-child(odd) { background: var(--row); }
   .slow td:first-child { width: 1%; } .slow td:last-child, .slow th:last-child { text-align: left; white-space: normal; width: auto; } .err { color: #d73a49; }
   .wrap { overflow-x: auto; }
+  ol.findings { padding-left: 20px; margin: 0; } ol.findings li { margin: 4px 0; } ol.findings a { color: inherit; }
+  .at { color: var(--muted); font-size: 12px; }
+  rect.ev { fill: #f0b400; fill-opacity: 0; stroke: none; pointer-events: none; }
+  rect.ev:target { fill-opacity: 0.22; stroke: #f0b400; stroke-width: 2; }
 </style>
 </head>
 <body>
 <main>
 <h1>${esc(title)}</h1>
 <p class="meta">${calls.length} calls · ${Object.keys(stats).length} labels · ${lanes.length} lane${lanes.length === 1 ? '' : 's'} · span ${esc(ms(span))}. Hover a bar for details.</p>
-<h2>Flame chart</h2>
+${findingsSection}
+<h2 id="chart">Flame chart</h2>
 <div class="chart"><svg width="${width}" height="${height}" viewBox="0 0 ${width} ${height}" role="img" aria-label="flame chart">
 ${ticks}
 ${rects}
+${bands.join('\n')}
 </svg></div>
 <h2>Statistics (ms)</h2>
 <div class="wrap"><table><thead><tr><th>label</th><th>calls</th><th>errors</th><th>total</th><th>mean</th><th>p50</th><th>p95</th><th>p99</th><th>max</th><th>self mean</th></tr></thead>

src/run.ts

@@ -351,7 +351,7 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise<number> {
     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));