Skip to content

Commit b6e660f

Browse files
feat: concrete fix suggestions for each finding
1 parent 12c3e6b commit b6e660f

4 files changed

Lines changed: 77 additions & 5 deletions

File tree

‎CHANGELOG.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
99

1010
### Added
1111
- **`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`.
12+
- **Fix suggestions:** findings now say what to change (`fix` in `explain()` / `--json`, a `fix:` line in text, under each finding in HTML): `Promise.all` for sequential awaits, `WHERE id IN (...)` / DataLoader for N+1, the async API for `pbkdf2Sync`, `readFileSync` and Sync zlib, a worker thread or chunking for hot loops, `EXPLAIN ANALYZE` for a dominant query.
1213
- **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.
1314
- **Known-slow example apps** (`examples/slow-apps/`): one planted cause each; a test checks that `explain` names it.
1415
- **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.

‎src/__tests__/explain-auto-profile.test.ts‎

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -58,6 +58,22 @@ describe('explain()', () => {
5858
expect(explain([n1]).find(f => f.kind === 'repeated')!.evidence).toEqual({ start: 5, end: 59, labels: ['q'] });
5959
});
6060

61+
test('findings carry a concrete fix that matches the cause', () => {
62+
const seq = node('page', 0, 30, { children: [node('loadUser', 0, 10), node('loadOrders', 10, 10)] });
63+
expect(explain([seq]).find(f => f.kind === 'sequential')!.fix).toBe("if they don't depend on each other, start them together: await Promise.all([loadUser(), loadOrders()])");
64+
const n1 = node('list', 0, 60, { children: Array.from({ length: 6 }, (_, i) => node('pg SELECT items', 5 + i * 9, 9)) });
65+
expect(explain([n1]).find(f => f.kind === 'repeated')!.fix).toMatch(/IN \(\.\.\.\)/);
66+
const rest = node('list', 0, 60, { children: Array.from({ length: 6 }, (_, i) => node('fetchUser', 5 + i * 9, 9)) });
67+
expect(explain([rest]).find(f => f.kind === 'repeated')!.fix).toMatch(/DataLoader/);
68+
const hash = node('login', 0, 30, { async: false, syncDuration: 30 });
69+
const hotspots = { login: [{ functionName: 'hashPassword → pbkdf2Sync', location: 'a.js:3', ms: 28 }, { functionName: '(garbage collection)', location: '', ms: 2 }] };
70+
const blocking = explain([hash], { hotspots }).find(f => f.kind === 'blocking')!;
71+
expect(blocking.fix).toMatch(/^hashPassword: use the async version/);
72+
expect(formatFindings([blocking])).toMatch(/\n {3}fix: hashPassword/);
73+
expect(explain([hash]).find(f => f.kind === 'blocking')!.fix).toMatch(/worker_threads/);
74+
expect(explain([node('boom', 0, 10, { error: new Error('x') })])[0].fix).toBeUndefined();
75+
});
76+
6177
test('blocking is attributed to the deepest call that did it', () => {
6278
const inner = node('parseJson', 0, 40, { async: false, syncDuration: 40 });
6379
const outer = node('handler', 0, 42, { async: false, syncDuration: 42, children: [inner] });

‎src/core/explain.ts‎

Lines changed: 56 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,8 @@ export interface Finding {
3535
ms: number;
3636
/** For blocking / blocked: the call whose synchronous code blocked */
3737
call?: string;
38+
/** What to change, when the cause suggests a concrete fix */
39+
fix?: string;
3840
/** Where to look: the time range (same clock as the input) and the calls involved */
3941
evidence?: FindingEvidence;
4042
}
@@ -336,6 +338,8 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin
336338
.map(({ times, roots: seenIn, group, ...f }) => {
337339
const where = [...seenIn];
338340
const label = where.length > 3 ? `${where.slice(0, 3).join(', ')} and ${where.length - 3} more` : where.join(', ');
341+
const fix = suggestFix(f, options.hotspots);
342+
if (fix) f = { ...f, fix };
339343
if (f.kind === 'blocking') {
340344
const self = where.length === 1 && where[0] === f.message.split(' ran ')[0];
341345
const count = times > where.length ? `${times} times` : '';
@@ -346,12 +350,62 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin
346350
});
347351
}
348352

353+
const SYNC_FIX: Array<[RegExp, string]> = [
354+
[/pbkdf2Sync|scryptSync/, 'use the async version (crypto.pbkdf2 / crypto.scrypt with a callback or util.promisify): it runs on the thread pool'],
355+
[/(randomBytes|generateKeyPairSync|hashSync|compareSync)/, 'use the async version of $1 so the work leaves the event loop'],
356+
[/readFileSync|writeFileSync|readdirSync|statSync|existsSync/, 'use fs.promises instead of the Sync call, or read it once at startup and cache it'],
357+
[/zlib|gzipSync|inflateSync|deflateSync|brotli/i, 'use the async / streaming zlib API instead of the Sync call'],
358+
[/JSON\.(stringify|parse)/, 'the payload is large: paginate it, send fewer fields, or stream it (e.g. a streaming JSON encoder)'],
359+
[/garbage collection/, 'it allocates a lot: reuse objects/buffers and avoid building large temporary arrays or strings'],
360+
];
361+
const SQL = /\b(select|insert|update|delete|pg|mysql|postgres|sql|query|prisma|knex|sequelize|typeorm|drizzle)\b/i;
362+
363+
/** A concrete change for a finding, from its kind, labels and CPU hotspots */
364+
function suggestFix(f: Finding, hotspots?: Record<string, BlockingHotspot[]>): string | undefined {
365+
const labels = f.evidence?.labels || [];
366+
switch (f.kind) {
367+
case 'blocked':
368+
case 'blocking': {
369+
const spots = (f.call && hotspots?.[f.call]) || [];
370+
// Only the top culprit decides: a 10% GC share is not the fix for a hot loop
371+
for (const h of spots.slice(0, 1)) {
372+
const name = `${h.functionName} ${h.location}`;
373+
for (const [re, fix] of SYNC_FIX) {
374+
const m = name.match(re);
375+
if (m) return `${h.functionName.split(' → ')[0]}: ${fix.replace('$1', m[1] || '')}`;
376+
}
377+
}
378+
const at = spots[0] ? `${spots[0].functionName.split(' → ')[0]}${spots[0].location ? ` (${spots[0].location})` : ''}` : f.call;
379+
return `move the CPU work in ${at} off the request path: a worker_threads Worker (e.g. a pool like piscina), split it into chunks with setImmediate, or cache its result`;
380+
}
381+
case 'sequential': {
382+
const names = labels.slice(0, 3);
383+
if (!names.every(n => /^[\w.$]+$/.test(n))) return `if they don't depend on each other, start them together with Promise.all instead of awaiting each in turn`;
384+
return `if they don't depend on each other, start them together: await Promise.all([${names.map(n => `${n}()`).join(', ')}${labels.length > 3 ? ', ...' : ''}])`;
385+
}
386+
case 'repeated': {
387+
const label = labels[0] || '';
388+
return SQL.test(label)
389+
? `load them in one query: WHERE id IN (...) (or = ANY($1) in Postgres), or your ORM's include/join; then match results in memory`
390+
: `make one batched call instead of one per item (a bulk API, or DataLoader to collect the calls of one tick)`;
391+
}
392+
case 'dominant':
393+
// Outside tracked code: the message says what to do; waited: the blocking finding has the fix
394+
if (f.message.includes('outside any tracked call') || f.message.includes('waiting for blocking code')) return undefined;
395+
return SQL.test(labels[0] || '')
396+
? `check this query's plan (EXPLAIN ANALYZE) and indexes, or cache its result`
397+
: `that is where the time goes: track or profile inside ${labels[0] || 'it'} next`;
398+
default:
399+
return undefined;
400+
}
401+
}
402+
349403
const ICON: Record<FindingKind, string> = {
350404
error: '✖', blocked: '⏳', blocking: '🔥', repeated: '🔁', sequential: '⇉', dominant: '●',
351405
};
352406

353-
/** Render findings as text, one per line */
407+
/** Render findings as text, one per line (and the fix, if any, below it) */
354408
export function formatFindings(findings: Finding[]): string {
355409
if (findings.length === 0) return 'No issues found: nothing blocked, repeated, or ran sequentially in a way worth changing.';
356-
return findings.map(f => `${ICON[f.kind]} ${f.message}`).join('\n');
410+
return findings.map(f => `${ICON[f.kind] || '•'} ${f.message}${f.fix ? `\n fix: ${f.fix}` : ''}`).join('\n');
357411
}

‎src/report-html.ts‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -70,9 +70,10 @@ export function renderHtmlReport(calls: Call[], stats: Record<string, LabelStats
7070
});
7171
const findingItems = findings.map((f, i) => {
7272
const text = `${ICON[f.kind] || '•'} ${esc(f.message)}`;
73+
const fix = f.fix ? `<div class="fix">fix: ${esc(f.fix)}</div>` : '';
7374
return bands[i]
74-
? `<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>`
75-
: `<li>${text}</li>`;
75+
? `<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>${fix}</li>`
76+
: `<li>${text}${fix}</li>`;
7677
}).join('\n');
7778
const findingsSection = findings.length
7879
? `<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>`
@@ -116,7 +117,7 @@ export function renderHtmlReport(calls: Call[], stats: Record<string, LabelStats
116117
.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; }
117118
.wrap { overflow-x: auto; }
118119
ol.findings { padding-left: 20px; margin: 0; } ol.findings li { margin: 4px 0; } ol.findings a { color: inherit; }
119-
.at { color: var(--muted); font-size: 12px; }
120+
.fix { color: var(--muted); font-size: 13px; } .at { color: var(--muted); font-size: 12px; }
120121
rect.ev { fill: #f0b400; fill-opacity: 0; stroke: none; pointer-events: none; }
121122
rect.ev:target { fill-opacity: 0.22; stroke: #f0b400; stroke-width: 2; }
122123
</style>

0 commit comments

Comments
 (0)