Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
2 changes: 1 addition & 1 deletion README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
```

Expand Down
19 changes: 19 additions & 0 deletions src/__tests__/cli.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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({
Expand Down
13 changes: 13 additions & 0 deletions src/__tests__/explain-auto-profile.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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] });
Expand Down
2 changes: 1 addition & 1 deletion src/__tests__/run.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
24 changes: 19 additions & 5 deletions src/cli.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand All @@ -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 {
Expand All @@ -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();
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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);
Expand Down
34 changes: 30 additions & 4 deletions src/core/explain.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
Expand All @@ -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)}`,
});
});
Expand All @@ -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)}`,
});
}
Expand Down Expand Up @@ -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)}`,
});
}
Expand Down Expand Up @@ -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)`,
});
}
Expand All @@ -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}`,
});
}
Expand All @@ -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`,
});
}
Expand All @@ -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}`,
});
});
Expand All @@ -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 };
Expand Down
33 changes: 31 additions & 2 deletions src/report-html.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;');
Expand All @@ -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;
Expand Down Expand Up @@ -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>`;
Expand Down Expand Up @@ -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>
Expand Down
2 changes: 1 addition & 1 deletion src/run.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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));
Expand Down
Loading