diff --git a/CHANGELOG.md b/CHANGELOG.md index 914bab6..9266a8f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,9 @@ 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`. - **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. +- `blockingRanges(root)`, `blockingHotspots(entries)`, `explain(roots, { hotspots })`; `profileSlowCalls({ select, mergeInlined })`; `summariseProfile(..., { mergeInlined })`; `Hotspot.hotLine`; `Finding.call`. - JSON lines include `startMs` (sub-millisecond start time); `traceperf explain` uses it when present. ### Changed diff --git a/README.md b/README.md index 485e3fe..6c23193 100644 --- a/README.md +++ b/README.md @@ -76,20 +76,26 @@ load: 230 requests in 5.0 s (46/s), 230× 200 ...per-route and per-query p50/p95/p99... Why it was slow: -⏳ GET /users waited ~165 ms (95% of its 174 ms) while GET /report blocked the event loop -🔥 GET /report ran 46 ms of synchronous code, blocking everything else in the process for that long +🔥 GET /report ran 48 ms of synchronous code, blocking everything else in the process for that long; CPU time: buildReport (server.js:10) 100% +⏳ GET /users waited ~165 ms (95% of its 174 ms) while GET /report blocked the event loop, in buildReport (server.js:10) ● SELECT * FROM users took 100% of GET /users (174 ms of 174 ms), but ~165 ms of that was waiting for blocking code elsewhere ``` -The database was fast; `GET /report` was blocking it. That only shows up when requests overlap, which is why `run` sends concurrent traffic. +The database was fast; `buildReport` was blocking it. That only shows up when requests overlap, which is why `run` sends concurrent traffic. + +- **The blocking function is named even though nothing tracks it:** `run` samples the CPU (the V8 profiler) during the synchronous part of each blocking call. Native work is named by the app function that called it (`hashPassword → pbkdf2Sync`), code V8 inlined is credited to the inlined function, and garbage-collection pauses are reported as such. `--no-profile` turns this off. +- **Queueing the app can't see:** a request that arrives while the event loop is blocked waits in the socket before its handler starts. `run` compares what its clients waited with the app's own timings and reports the difference. - `--path /x` (repeatable): what to request. Without `--path`, use the app yourself and press Ctrl-C for the report. - `-c 10` concurrency, `-d 5s` duration or `-n 500` requests, `--method POST`, `--port 3000` (detected by default). - `--html report.html`, `--output calls.jsonl` (keep the trees), `--json`. - `--warmup 3`: untimed requests per path first, so cold-start work doesn't look like a problem. +- `--no-profile`: don't sample the CPU. - Any start command works: `npx traceperf run -- npm start`. -`examples/slow-apps/` has small apps with one planted problem each (blocking, sequential awaits, N+1, a slow dependency, errors); CI checks that `run` names each one. +`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 })`. ## No code changes: `traceperf/auto` diff --git a/docs/production.md b/docs/production.md index 984197c..6cf442c 100644 --- a/docs/production.md +++ b/docs/production.md @@ -42,6 +42,7 @@ Measured on Node 24 (AMD EPYC). Reproduce with `npm run bench` and `npm run benc | Incoming request (`traceperf/auto`, `instrumentHttpServer`) | ~4.4 µs per request; ~1.4 µs when sampled out at 10% | | Writing each request tree as JSON lines | ~5 µs more per request (`JSON.stringify` plus the write) | | `profileSlowCalls` (V8 sampling profiler at 1 ms) | 0–6% CPU on CPU-bound code in our runs | +| `TRACEPERF_PROFILE_BLOCKING=1` (names blocking code) | the same sampling profiler; use while investigating | | OpenTelemetry span via the live exporter | ~16 µs per call (mostly the OpenTelemetry SDK itself) | A request that takes 1 ms pays well under 1% for full tracking. On a hello-world HTTP server running in a separate process, the difference with and without `traceperf/auto` was smaller than run-to-run noise. diff --git a/examples/slow-apps/README.md b/examples/slow-apps/README.md index d677450..865ec95 100644 --- a/examples/slow-apps/README.md +++ b/examples/slow-apps/README.md @@ -5,6 +5,7 @@ Each app has one planted performance problem. `traceperf run` should name it: | App | Planted problem | Try | |---|---|---| | `blocking/` | `GET /report` runs ~40 ms of synchronous code; other requests wait for it | `npx traceperf run examples/slow-apps/blocking/server.js --path /report --path /users` | +| `blocking-native/` | `JSON.stringify` of a big object and `crypto.pbkdf2Sync` block `GET /ping`; the profiler names the calling functions | `... blocking-native/server.js --path /export --path /login --path /ping` | | `sequential/` | three independent queries awaited one after another | `... sequential/server.js --path /dashboard` | | `n-plus-one/` | one query per order instead of one batched query | `... n-plus-one/server.js --path /orders` | | `slow-dependency/` | one downstream call takes nearly all the time | `... slow-dependency/server.js --path /checkout` | diff --git a/examples/slow-apps/blocking-native/server.js b/examples/slow-apps/blocking-native/server.js new file mode 100644 index 0000000..0e38ee0 --- /dev/null +++ b/examples/slow-apps/blocking-native/server.js @@ -0,0 +1,30 @@ +// Planted cause: blocking inside Node/V8 built-ins rather than your own +// loops. GET /export serialises a large object with JSON.stringify and +// GET /login hashes a password with crypto.pbkdf2Sync; both block every +// other request (GET /ping) while they run. +const crypto = require('crypto'); +const serve = require('../serve'); + +const catalog = Array.from({ length: 20000 }, (_, i) => ({ id: i, name: `item ${i}`, tags: ['a', 'b', 'c'], price: i * 1.5 })); + +// Each runs for ~25 ms on any machine (repeating the work), so the example +// behaves the same on a fast CI runner and a slow laptop +function exportCatalog() { + let bytes = 0; + const until = Date.now() + 25; + do bytes = JSON.stringify(catalog).length; while (Date.now() < until); + return bytes; +} + +function hashPassword(password) { + let hash; + const until = Date.now() + 25; + do hash = crypto.pbkdf2Sync(password, 'salt', 5000, 32, 'sha256'); while (Date.now() < until); + return hash.toString('hex'); +} + +serve({ + '/export': async () => ({ bytes: exportCatalog() }), + '/login': async () => ({ hash: hashPassword('hunter2').slice(0, 8) }), + '/ping': async () => ({ ok: true }), +}); diff --git a/examples/slow-apps/cases.json b/examples/slow-apps/cases.json index 0a46b8e..2951abe 100644 --- a/examples/slow-apps/cases.json +++ b/examples/slow-apps/cases.json @@ -1,25 +1,87 @@ { "blocking": { - "paths": ["/report", "/users"], + "paths": [ + "/report", + "/users" + ], "expect": [ - { "kind": "blocking", "includes": "GET /report" }, - { "kind": "blocked", "includes": "GET /report" } + { + "kind": "blocking", + "includes": "GET /report" + }, + { + "kind": "blocking", + "includes": "buildReport" + }, + { + "kind": "blocked", + "includes": "GET /report" + } ] }, "sequential": { - "paths": ["/dashboard"], - "expect": [{ "kind": "sequential", "includes": "awaited 3 calls" }] + "paths": [ + "/dashboard" + ], + "expect": [ + { + "kind": "sequential", + "includes": "awaited 3 calls" + } + ] }, "n-plus-one": { - "paths": ["/orders"], - "expect": [{ "kind": "repeated", "includes": "SELECT * FROM items WHERE order_id = ? 12 times" }] + "paths": [ + "/orders" + ], + "expect": [ + { + "kind": "repeated", + "includes": "SELECT * FROM items WHERE order_id = ? 12 times" + } + ] }, "slow-dependency": { - "paths": ["/checkout"], - "expect": [{ "kind": "dominant", "includes": "POST payments.example/charge" }] + "paths": [ + "/checkout" + ], + "expect": [ + { + "kind": "dominant", + "includes": "POST payments.example/charge" + } + ] }, "errors": { - "paths": ["/pay"], - "expect": [{ "kind": "error", "includes": "payment provider timed out" }] + "paths": [ + "/pay" + ], + "expect": [ + { + "kind": "error", + "includes": "payment provider timed out" + } + ] + }, + "blocking-native": { + "paths": [ + "/export", + "/login", + "/ping" + ], + "expect": [ + { + "kind": "blocking", + "includes": "exportCatalog" + }, + { + "kind": "blocking", + "includes": "hashPassword → pbkdf2Sync" + }, + { + "kind": "blocked", + "includes": "GET /ping took" + } + ] } } diff --git a/src/__tests__/run.test.ts b/src/__tests__/run.test.ts index 994683d..6222f21 100644 --- a/src/__tests__/run.test.ts +++ b/src/__tests__/run.test.ts @@ -169,3 +169,87 @@ describe('runApp', () => { expect(out.join('\n')).toContain('no requests were tracked'); }, 30000); }); + +describe('naming blocking code from CPU profiles', () => { + // A tiny V8-shaped profile: root > handler > buildReport, plus samples where + // buildReport was inlined into handler (attributed to handler), and a native + // frame under hashPassword > pbkdf2Sync (node:internal) + const { summariseProfile, createInlineHints, learnInlineHints, blockingHotspots } = jest.requireActual('../core/cpu-profile'); + const frame = (functionName: string, url: string, lineNumber: number) => ({ functionName, url, lineNumber, columnNumber: 0, scriptId: '1' }); + const profile = { + startTime: 0, + nodes: [ + { id: 1, callFrame: frame('(root)', '', -1), children: [2, 5] }, + { id: 2, callFrame: frame('handler', 'file:///app/server.js', 14), children: [3], positionTicks: [{ line: 15, ticks: 6 }] }, + { id: 3, callFrame: frame('buildReport', 'file:///app/server.js', 2), children: [], positionTicks: [{ line: 6, ticks: 4 }] }, + { id: 5, callFrame: frame('hashPassword', 'file:///app/server.js', 19), children: [6] }, + { id: 6, callFrame: frame('pbkdf2Sync', 'node:internal/crypto/pbkdf2', 40), children: [7] }, + { id: 7, callFrame: frame('run', '', -1), children: [] }, + ], + // 6 samples in handler (inlined buildReport), 4 in buildReport, 5 native + samples: [2, 2, 2, 2, 2, 2, 3, 3, 3, 3, 7, 7, 7, 7, 7], + timeDeltas: Array(15).fill(1000), + }; + + it('without merging, self time stays where V8 put it', () => { + const p = summariseProfile(profile, 0, 100, 5); + expect(p.hotspots[0].functionName).toBe('handler'); + }); + + it('moves inlined self time to the callee and names native code by its caller', () => { + const p = summariseProfile(profile, 0, 100, 5, undefined, { mergeInlined: true }); + const names = p.hotspots.map((h: any) => h.functionName); + expect(names[0]).toBe('buildReport'); + expect(p.hotspots[0].selfMs).toBeCloseTo(10, 0); + expect(p.hotspots[0].hotLine).toBe(6); + expect(names).toContain('hashPassword → pbkdf2Sync'); + expect(names).not.toContain('handler'); + }); + + it('remembers callers across windows, when a later window only has the inlined form', () => { + const hints = createInlineHints(); + learnInlineHints(profile, hints); + const later = { ...profile, nodes: profile.nodes.map(n => (n.id === 2 ? { ...n, children: [] } : n)).filter(n => n.id !== 3), samples: [2, 2, 2], timeDeltas: [1000, 1000, 1000] }; + learnInlineHints(later, hints); + const p = summariseProfile(later, 0, 100, 5, undefined, { mergeInlined: hints }); + expect(p.hotspots[0].functionName).toBe('buildReport'); + }); + + it('sums hotspots per label and function, with paths relative to cwd', () => { + const spots = blockingHotspots([ + { label: 'GET /r', hotspots: [{ functionName: 'f', url: 'file:///app/a.js', line: 3, column: 1, selfMs: 4, hotLine: 5 }] }, + { label: 'GET /r', hotspots: [{ functionName: 'f', url: 'file:///app/a.js', line: 3, column: 1, selfMs: 1 }, { functionName: 'g', url: '', line: 0, column: 0, selfMs: 2 }] }, + ], { cwd: '/app' }); + expect(spots['GET /r']).toEqual([ + { functionName: 'f', location: 'a.js:5', ms: 5 }, + { functionName: 'g', location: '', ms: 2 }, + ]); + }); + + it('explain names the function in blocking and blocked findings', () => { + const roots: ExplainNode[] = [ + { label: 'GET /report', startTime: 0, duration: 40, selfDuration: 40, syncDuration: 40, async: true, children: [] }, + { label: 'GET /users', startTime: 1, duration: 45, selfDuration: 45, syncDuration: 0, async: true, children: [] }, + ]; + const findings = explain(roots, { hotspots: { 'GET /report': [{ functionName: 'buildReport', location: 'server.js:10', ms: 38 }, { functionName: 'tiny', location: 'x.js:1', ms: 0.5 }] } }); + const blocking = findings.find(f => f.kind === 'blocking')!; + expect(blocking.message).toContain('CPU time: buildReport (server.js:10) 99%'); + expect(blocking.message).not.toContain('tiny'); // under 5% + expect(blocking.call).toBe('GET /report'); + expect(findings.find(f => f.kind === 'blocked')!.message).toContain('blocked the event loop, in buildReport (server.js:10)'); + }); +}); + +describe('queueFindings', () => { + const { queueFindings } = jest.requireActual('../run'); + it('reports time clients waited that the app never saw', () => { + const load = { requests: 4, errors: 0, statuses: {}, durationMs: 1, latency: { '/ping': [180, 190, 185, 200], '/slow': [60, 61, 59, 60] } }; + const trees = [ + ...[0.2, 0.3, 0.2, 0.2].map(d => ({ label: 'GET /ping', duration: d })), + ...[55, 58, 57, 56].map(d => ({ label: 'GET /slow', duration: d })), + ]; + const findings = queueFindings(load, trees, 'GET'); + expect(findings).toHaveLength(1); + expect(findings[0].message).toContain('GET /ping took 0.2 ms in the app (median) but clients waited 190 ms'); + }); +}); diff --git a/src/core/cpu-profile.ts b/src/core/cpu-profile.ts index bc30640..5d0fa9d 100644 --- a/src/core/cpu-profile.ts +++ b/src/core/cpu-profile.ts @@ -27,6 +27,8 @@ export interface Hotspot { column: number; /** CPU time sampled in this function itself, in ms */ selfMs: number; + /** The line in it with the most samples, when the profile has line ticks */ + hotLine?: number; } export interface SlowCallProfile { @@ -55,6 +57,18 @@ export interface ProfileSlowCallsOptions { top?: number; /** Skip functions from these paths, e.g. /node_modules/ (default: none) */ exclude?: RegExp; + /** + * Attribute a function's own samples to the callee seen running under it + * the most, recovering code V8 inlined into its caller (default false) + */ + mergeInlined?: boolean; + /** + * Choose what to profile in each finished tree: calls and time ranges + * (performance.now ms). Default: the top-level call, when at least + * `threshold` ms. Use it to profile, say, only the synchronous part of + * calls that blocked the event loop. + */ + select?: (root: ExecutionRecord) => Array<{ call: ExecutionRecord; start: number; end: number }>; } export interface SlowCallProfiler extends TracePerfPlugin { @@ -70,6 +84,8 @@ export interface SlowCallProfiler extends TracePerfPlugin { export interface CpuProfileNode { id: number; callFrame: { functionName: string; url: string; lineNumber: number; columnNumber: number }; + /** Samples per source line (1-based), for the whole profile */ + positionTicks?: Array<{ line: number; ticks: number }>; } /** A V8 CPU profile (inspector Profiler.stop result) */ export interface CpuProfile { @@ -79,10 +95,148 @@ export interface CpuProfile { timeDeltas: number[]; } -/** Summarise the samples of a profile that fall within [start, end] (ms, profile clock) */ -export function summariseProfile(profile: CpuProfile, start: number, end: number, top = 5, exclude?: RegExp): SlowCallProfile { +/** + * What the profiler learned about which functions call which, kept across + * profile windows. V8 attributes code it inlined to the caller (at the + * call-site line), and once code is optimized a window may contain only the + * inlined form; earlier windows still show the real callee. + */ +export interface InlineHints { + callees: Map>; + frames: Map; +} + +export function createInlineHints(): InlineHints { + return { callees: new Map(), frames: new Map() }; +} + +const isUserFrame = (n: CpuProfileNode | undefined, exclude?: RegExp): boolean => + !!n && !!n.callFrame.url && !n.callFrame.url.startsWith('node:') && !(exclude && exclude.test(n.callFrame.url)); +const fnKey = (n: CpuProfileNode): string => + `${n.callFrame.functionName}|${n.callFrame.url}|${n.callFrame.lineNumber}|${n.callFrame.columnNumber}`; +const hottestLine = (n: CpuProfileNode): number | undefined => + n.positionTicks && n.positionTicks.length ? n.positionTicks.reduce((a, b) => (b.ticks > a.ticks ? b : a)).line : undefined; + +/** Add a profile's caller -> callee sample counts (by function) to the hints */ +export function learnInlineHints(profile: CpuProfile, hints: InlineHints, exclude?: RegExp): void { const nodes = new Map(profile.nodes.map(n => [n.id, n])); + const hits = new Map(); + for (const id of profile.samples) hits.set(id, (hits.get(id) || 0) + 1); + const subtree = new Map(); + const total = (id: number): number => { + const cached = subtree.get(id); + if (cached !== undefined) return cached; + subtree.set(id, 0); // guards against cycles in malformed input + const sum = (hits.get(id) || 0) + ((nodes.get(id) as any)?.children || []).reduce((acc: number, c: number) => acc + total(c), 0); + subtree.set(id, sum); + return sum; + }; + for (const n of profile.nodes) { + if (!isUserFrame(n, exclude)) continue; + const key = fnKey(n); + const own = hits.get(n.id) || 0; + const frame = hints.frames.get(key); + // Remember where the function itself is hot, from its non-inlined samples + if (!frame || own > frame.hits) { + hints.frames.set(key, { + name: n.callFrame.functionName || '(anonymous)', url: n.callFrame.url, + line: n.callFrame.lineNumber + 1, column: n.callFrame.columnNumber + 1, hotLine: hottestLine(n), hits: own, + }); + } + for (const c of (n as any).children || []) { + const child = nodes.get(c); + if (!isUserFrame(child, exclude) || total(c) === 0) continue; + const ck = fnKey(child as CpuProfileNode); + if (ck === key) continue; + const m = hints.callees.get(key) ?? new Map(); + m.set(ck, (m.get(ck) || 0) + total(c)); + hints.callees.set(key, m); + } + } +} + +/** + * Summarise the samples of a profile that fall within [start, end] (ms, + * profile clock). With `mergeInlined` (true, or hints kept across profiles), + * a function's own samples move to the callee seen running under it the most + * (recursively): most likely the code V8 inlined there. + */ +export function summariseProfile(profile: CpuProfile, start: number, end: number, top = 5, exclude?: RegExp, options: { mergeInlined?: boolean | InlineHints } = {}): SlowCallProfile { + const nodes = new Map(profile.nodes.map(n => [n.id, n])); + let hints: InlineHints | undefined; + if (options.mergeInlined) { + hints = options.mergeInlined === true ? createInlineHints() : options.mergeInlined; + if (options.mergeInlined === true) learnInlineHints(profile, hints, exclude); + } const self = new Map(); + // Function start lines per script, to recover functions V8 inlined into a caller + const starts = new Map>(); + for (const n of profile.nodes) { + const f = n.callFrame; + if (!f.url || !f.functionName) continue; + const list = starts.get(f.url) ?? []; + if (!list.some(x => x.line === f.lineNumber + 1 && x.name === f.functionName)) list.push({ line: f.lineNumber + 1, column: f.columnNumber + 1, name: f.functionName }); + starts.set(f.url, list); + } + type Frame = { name: string; url: string; line: number; column: number; hotLine?: number }; + const resolved = new Map(); + const parent = new Map(); + if (hints) for (const n of profile.nodes) for (const c of (n as any).children || []) parent.set(c, n.id); + const SPECIAL = /^\((idle|garbage collector|program|root)\)$/; + /** The function a sample is really in, and its hottest line */ + const locate = (node: CpuProfileNode): Frame => { + const cached = resolved.get(node.id); + if (cached) return cached; + const { functionName, url, lineNumber, columnNumber } = node.callFrame; + let frame: Frame = { name: functionName || '(anonymous)', url, line: lineNumber + 1, column: columnNumber + 1 }; + const hotLine = hottestLine(node); + if (hotLine !== undefined) frame.hotLine = hotLine; + // Native code and Node internals: name the nearest calling function of + // the app, and the Node API in between ("hashPassword → pbkdf2Sync") + if (hints && !isUserFrame(node, exclude) && !SPECIAL.test(functionName)) { + let api = ''; + let id = parent.get(node.id); + for (let depth = 0; id !== undefined && depth < 64; depth++, id = parent.get(id)) { + const up = nodes.get(id); + if (!up) break; + if (isUserFrame(up, exclude)) { + const inner = api || functionName || '(native)'; + frame = { + name: `${up.callFrame.functionName || '(anonymous)'} → ${inner}`, + url: up.callFrame.url, line: up.callFrame.lineNumber + 1, column: up.callFrame.columnNumber + 1, + }; + const callLine = hottestLine(up); + if (callLine !== undefined) frame.hotLine = callLine; + break; + } + // The outermost Node API frame below the app's code + if (up.callFrame.functionName && up.callFrame.url.startsWith('node:')) api = up.callFrame.functionName; + } + } else if (hints && isUserFrame(node, exclude)) { + let key = fnKey(node); + const seen = new Set([key]); + for (let depth = 0; depth < 64; depth++) { + const m = hints.callees.get(key); + if (!m || m.size === 0) break; + const next = [...m.entries()].reduce((a, b) => (b[1] > a[1] ? b : a))[0]; + if (seen.has(next)) break; + seen.add(next); + key = next; + } + const f = key !== fnKey(node) ? hints.frames.get(key) : undefined; + if (f) frame = { name: f.name, url: f.url, line: f.line, column: f.column, ...(f.hotLine !== undefined ? { hotLine: f.hotLine } : {}) }; + } else if (hotLine !== undefined && hotLine < frame.line) { + // A hot line before the function even starts belongs to an inlined + // callee: the function defined nearest above that line in the script + const candidates = (starts.get(url) || []).filter(x => x.line <= hotLine); + if (candidates.length) { + const fn = candidates.reduce((a, b) => (b.line > a.line ? b : a)); + frame = { name: fn.name, url, line: fn.line, column: fn.column, hotLine }; + } + } + resolved.set(node.id, frame); + return frame; + }; let idleMs = 0; let gcMs = 0; let cpuMs = 0; @@ -96,7 +250,7 @@ export function summariseProfile(profile: CpuProfile, start: number, end: number samples++; const node = nodes.get(profile.samples[i]); if (!node) continue; - const { functionName, url, lineNumber, columnNumber } = node.callFrame; + const { functionName, url } = node.callFrame; if (functionName === '(idle)') { idleMs += next; continue; @@ -111,9 +265,11 @@ export function summariseProfile(profile: CpuProfile, start: number, end: number } cpuMs += next; if (exclude && exclude.test(url)) continue; - const key = `${functionName}|${url}|${lineNumber}|${columnNumber}`; + const at = locate(node); + const key = `${at.name}|${at.url}|${at.line}|${at.column}|${at.hotLine}`; const entry = self.get(key) ?? { - functionName: functionName || '(anonymous)', url, line: lineNumber + 1, column: columnNumber + 1, selfMs: 0, + functionName: at.name, url: at.url, line: at.line, column: at.column, selfMs: 0, + ...(at.hotLine !== undefined ? { hotLine: at.hotLine } : {}), }; entry.selfMs += next; self.set(key, entry); @@ -125,7 +281,7 @@ export function summariseProfile(profile: CpuProfile, start: number, end: number function mergeProfiles(a: SlowCallProfile, b: SlowCallProfile, top: number): SlowCallProfile { const all = new Map(); for (const h of [...a.hotspots, ...b.hotspots]) { - const key = `${h.functionName}|${h.url}|${h.line}|${h.column}`; + const key = `${h.functionName}|${h.url}|${h.line}|${h.column}|${h.hotLine}`; const e = all.get(key); if (e) e.selfMs += h.selfMs; else all.set(key, { ...h }); @@ -152,6 +308,49 @@ const nowMs = (): number => { return perf ? perf.now() : Date.now(); }; +/** One profiled blocking call, as written by traceperf/auto (TRACEPERF_PROFILE_OUTPUT) */ +export interface BlockingProfileEntry { + label: string; + hotspots: Hotspot[]; +} + +/** + * Sum hotspots per call label across many blocking calls, largest first. + * Locations become "path:line", relative to `cwd` when inside it. + */ +export function blockingHotspots(entries: BlockingProfileEntry[], options: { cwd?: string; top?: number } = {}): Record> { + const byLabel = new Map }>>(); + const cwd = options.cwd ? options.cwd.replace(/\\/g, '/').replace(/\/?$/, '/') : undefined; + for (const entry of entries) { + const spots = byLabel.get(entry.label) ?? new Map(); + byLabel.set(entry.label, spots); + for (const h of entry.hotspots) { + let file = h.url.replace(/^file:\/\//, ''); + try { + file = decodeURIComponent(file); + } catch { + // keep as is + } + if (cwd && file.startsWith(cwd)) file = file.slice(cwd.length); + const location = file ? `${file}:${h.hotLine ?? h.line}` : ''; + // One entry per function; it shows the line with the most time + const key = `${h.functionName}|${file}`; + const spot = spots.get(key) ?? { functionName: h.functionName || '(anonymous)', location, ms: 0, lines: new Map() }; + spot.ms += h.selfMs; + spot.lines.set(location, (spot.lines.get(location) || 0) + h.selfMs); + spots.set(key, spot); + } + } + const out: Record> = {}; + byLabel.forEach((spots, label) => { + out[label] = [...spots.values()] + .map(({ lines, ...spot }) => ({ ...spot, location: [...lines.entries()].reduce((a, b) => (b[1] > a[1] ? b : a))[0] })) + .sort((a, b) => b.ms - a.ms) + .slice(0, options.top ?? 5); + }); + return out; +} + export function profileSlowCalls(options: ProfileSlowCallsOptions): SlowCallProfiler { const threshold = options.threshold ?? 100; const windowMs = options.window ?? 2000; @@ -160,7 +359,7 @@ export function profileSlowCalls(options: ProfileSlowCallsOptions): SlowCallProf const inspector = loadNodeBuiltin('inspector'); const available = !!(inspector && inspector.Session); let session: any; - let pending: ExecutionRecord[] = []; + let pending: Array<{ call: ExecutionRecord; start: number; end: number }> = []; /** performance.now() at the profile's start, and the profile's own start (ms) */ let windowStartNow = 0; let stopped = false; @@ -168,6 +367,7 @@ export function profileSlowCalls(options: ProfileSlowCallsOptions): SlowCallProf let busy: Promise = Promise.resolve(); /** The previous window, for calls that started before the current one */ let previous: { profile: CpuProfile; offset: number; startNow: number } | undefined; + const hints = options.mergeInlined ? createInlineHints() : undefined; const post = (method: string, params?: object): Promise => new Promise((resolve, reject) => { session.post(method, params || {}, (err: unknown, result: unknown) => (err ? reject(err) : resolve(result))); @@ -186,12 +386,13 @@ export function profileSlowCalls(options: ProfileSlowCallsOptions): SlowCallProf const startNow = windowStartNow; const { profile } = await post('Profiler.stop'); if (restart && !stopped) await startWindow(); + if (hints) learnInlineHints(profile, hints, options.exclude); // Map the call's times (performance.now clock) onto the profile clock const offset = profile.startTime / 1000 - startNow; - for (const call of calls) { - let result = summariseProfile(profile, call.startTime + offset, call.endTime + offset, top, options.exclude); - if (previous && call.startTime < startNow) { - const earlier = summariseProfile(previous.profile, call.startTime + previous.offset, call.endTime + previous.offset, top, options.exclude); + for (const { call, start, end } of calls) { + let result = summariseProfile(profile, start + offset, end + offset, top, options.exclude, { mergeInlined: hints }); + if (previous && start < startNow) { + const earlier = summariseProfile(previous.profile, start + previous.offset, end + previous.offset, top, options.exclude, { mergeInlined: hints }); result = mergeProfiles(earlier, result, top); } try { @@ -224,9 +425,13 @@ export function profileSlowCalls(options: ProfileSlowCallsOptions): SlowCallProf name: 'profile-slow-calls', available, onComplete(root) { - if (!session || stopped || root.duration < threshold) return; - // Calls reaching back further than the previous window are skipped - if (root.startTime >= (previous ? previous.startNow : windowStartNow)) pending.push(root); + if (!session || stopped) return; + const ranges = options.select + ? options.select(root) + : root.duration >= threshold ? [{ call: root, start: root.startTime, end: root.endTime }] : []; + // Ranges reaching back further than the previous window are skipped + const earliest = previous ? previous.startNow : windowStartNow; + for (const range of ranges) if (range.start >= earliest) pending.push(range); }, flush: () => rotate(true), async stop() { diff --git a/src/core/explain.ts b/src/core/explain.ts index 5bf8b1d..7887229 100644 --- a/src/core/explain.ts +++ b/src/core/explain.ts @@ -33,6 +33,17 @@ export interface Finding { message: string; /** Estimated milliseconds involved (delay, possible saving, or time taken) */ ms: number; + /** For blocking / blocked: the call whose synchronous code blocked */ + call?: string; +} + +/** Where a blocking call spent its CPU time (from the sampling profiler) */ +export interface BlockingHotspot { + functionName: string; + /** File and line, e.g. "src/report.js:12" ("" for native code) */ + location: string; + /** Sampled self time, ms */ + ms: number; } export interface ExplainOptions { @@ -46,6 +57,11 @@ export interface ExplainOptions { repeatCount?: number; /** Return at most this many findings, largest first (default 20) */ max?: number; + /** + * CPU hotspots per blocking call label, e.g. from profileSlowCalls with + * blockingRanges(): blocking findings then name the function that ran. + */ + hotspots?: Record; } const fmt = (ms: number): string => (ms >= 1000 ? `${(ms / 1000).toFixed(2)} s` : `${ms.toFixed(ms < 10 ? 1 : 0)} ms`); @@ -57,6 +73,7 @@ function syncOf(node: ExplainNode): number { } interface Blocker { + node: ExplainNode; label: string; root: number; start: number; @@ -72,12 +89,23 @@ function collectBlockers(node: ExplainNode, rootIndex: number, threshold: number const sync = syncOf(node); // Attribute to this node only the blocking its blocking children do not explain if (sync >= threshold && sync - childBlocked >= threshold) { - out.push({ label: node.label, root: rootIndex, start: node.startTime, end: node.startTime + sync }); + out.push({ node, label: node.label, root: rootIndex, start: node.startTime, end: node.startTime + sync }); return true; } return childBlocked > 0; } +/** + * The calls whose synchronous code blocked the event loop for at least + * `blockingMs`, deepest first, with the blocking time range (same clock as + * the records). Pass to profileSlowCalls({ select }) to see what ran. + */ +export function blockingRanges(root: T, blockingMs = 10): Array<{ call: T; start: number; end: number }> { + const out: Blocker[] = []; + collectBlockers(root, 0, blockingMs, out); + return out.map(b => ({ call: b.node as T, start: b.start, end: b.end })); +} + function overlap(aStart: number, aEnd: number, bStart: number, bEnd: number): number { return Math.max(0, Math.min(aEnd, bEnd) - Math.max(aStart, bStart)); } @@ -94,6 +122,18 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin const repeatCount = options.repeatCount ?? 5; const findings: Array = []; + /** " (in fn, file:line)" / "; mostly fn (file:line) 80%, ..." from profiler samples */ + const culprit = (label: string, short: boolean): string => { + const all = options.hotspots?.[label] || []; + const total = all.reduce((sum, h) => sum + h.ms, 0); + const spots = all.filter(h => h.ms >= 0.05 * total); + if (spots.length === 0) return ''; + const at = (h: BlockingHotspot) => `${h.functionName}${h.location ? ` (${h.location})` : ''}`; + if (short) return `, in ${at(spots[0])}`; + const shown = spots.slice(0, 3).map(h => `${at(h)} ${pct(h.ms, total)}`).join(', '); + return `; CPU time: ${shown}`; + }; + const blockers: Blocker[] = []; roots.forEach((root, i) => collectBlockers(root, i, blockingMs, blockers)); @@ -123,7 +163,8 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin kind: 'blocked', root: rootLabel, ms, - message: `${rootLabel} waited ~${fmt(ms)} (${pct(ms, root.duration)} of its ${fmt(root.duration)}) while ${label}${where} blocked the event loop`, + call: 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)}`, }); }); @@ -136,7 +177,8 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin kind: 'blocking', root: rootLabel, ms, - message: `${b.label} ran ${fmt(ms)} of synchronous code, blocking everything else in the process for that long`, + call: b.label, + message: `${b.label} ran ${fmt(ms)} of synchronous code, blocking everything else in the process for that long${culprit(b.label, false)}`, }); } diff --git a/src/register.ts b/src/register.ts index 824d893..17db759 100644 --- a/src/register.ts +++ b/src/register.ts @@ -15,12 +15,16 @@ * TRACEPERF_DISABLE=http,fetch skip targets (server, http, fetch, pg, mysql2, mongodb, ioredis) * TRACEPERF_IGNORE=^/health regular expression of request paths not to track * TRACEPERF_QUIET=1 no "traceperf: tracking ..." line at startup + * TRACEPERF_PROFILE_BLOCKING=1 sample the CPU (V8 profiler) to name the + * functions that blocked the event loop (a few % CPU) + * TRACEPERF_PROFILE_OUTPUT=f with it, append those profiles as JSON lines * TRACEPERF_ENABLED=0 load nothing */ import './node-builtins'; // must stay first: see node-builtins.ts import tracePerf from './index'; import { AUTO_TARGETS, AutoTarget, autoInstrument } from './auto'; -import { explain, formatFindings } from './core/explain'; +import { blockingRanges, explain, formatFindings } from './core/explain'; +import { BlockingProfileEntry, blockingHotspots, profileSlowCalls, SlowCallProfiler } from './core/cpu-profile'; import { jsonLinesExporter } from './core/exporters'; import { loadNodeBuiltin } from './core/env'; import type { ExecutionRecord } from './core/records'; @@ -58,6 +62,37 @@ if (flag(env.TRACEPERF_ENABLED, true) && !g[AUTO_KEY]) { }); } + // Name the code behind blocking: profile the synchronous part of blocking calls + const blockingEntries: BlockingProfileEntry[] = []; + let profiler: SlowCallProfiler | undefined; + if (flag(env.TRACEPERF_PROFILE_BLOCKING, false)) { + const profileOutput = env.TRACEPERF_PROFILE_OUTPUT; + profiler = profileSlowCalls({ + window: 1000, + mergeInlined: true, + select: root => blockingRanges(root), + exclude: /[\\/]traceperf[\\/]dist[\\/]/, + onProfile: (call, profile) => { + // Garbage collection during the blocking part counts as a culprit too + const hotspots = profile.gcMs >= 1 + ? [...profile.hotspots, { functionName: '(garbage collection)', url: '', line: 0, column: 0, selfMs: profile.gcMs }] + : profile.hotspots; + if (hotspots.length === 0) return; + const entry: BlockingProfileEntry = { label: call.label, hotspots }; + if (blockingEntries.length < 5000) blockingEntries.push(entry); + if (profileOutput && fs) { + try { + fs.appendFileSync(profileOutput, JSON.stringify(entry) + '\n'); + } catch { + // reporting must never break the app + } + } + }, + }); + if (profiler.available) tracePerf.use(profiler); + else profiler = undefined; + } + const disable = (env.TRACEPERF_DISABLE || '').split(',').map(s => s.trim()).filter(Boolean) as AutoTarget[]; const unknown = disable.filter(t => !AUTO_TARGETS.includes(t)); if (unknown.length) process.stderr.write(`traceperf: unknown TRACEPERF_DISABLE target(s): ${unknown.join(', ')}\n`); @@ -101,7 +136,8 @@ if (flag(env.TRACEPERF_ENABLED, true) && !g[AUTO_KEY]) { printed = true; const stats = tracePerf.getStats(); if (Object.keys(stats).length === 0) return; - process.stderr.write(`\ntraceperf summary\n\n${tracePerf.formatStats()}\n\n${formatFindings(explain(recent, { max: 10 }))}\n`); + const hotspots = blockingEntries.length ? blockingHotspots(blockingEntries, { cwd: process.cwd() }) : undefined; + process.stderr.write(`\ntraceperf summary\n\n${tracePerf.formatStats()}\n\n${formatFindings(explain(recent, { max: 10, hotspots }))}\n`); }; process.once('exit', printSummary); // Ctrl-C / kill: print, then exit as the signal would have, unless the app @@ -110,8 +146,15 @@ if (flag(env.TRACEPERF_ENABLED, true) && !g[AUTO_KEY]) { const onSignal = () => { if (process.listenerCount(signal) > 1) return; process.removeListener(signal, onSignal); - printSummary(); - process.kill(process.pid, signal); + const finish = () => { + printSummary(); + process.kill(process.pid, signal); + }; + // Deliver the last profiler window first (bounded, so exit is never stuck) + if (profiler) { + const guard = setTimeout(finish, 2000); + profiler.stop().then(() => { clearTimeout(guard); finish(); }, finish); + } else finish(); }; process.on(signal, onSignal); } diff --git a/src/run.ts b/src/run.ts index 512320b..9b6849c 100644 --- a/src/run.ts +++ b/src/run.ts @@ -9,6 +9,8 @@ * Node-only; builtins are passed in so this module stays free of require(). */ import { explain, formatFindings, Finding } from './core/explain'; +import { blockingHotspots, BlockingProfileEntry } from './core/cpu-profile'; +import { normalizePath } from './instrument'; export interface RunArgs { /** Command and its arguments; a .js/.mjs/.cjs file runs with this Node */ @@ -26,6 +28,8 @@ export interface RunArgs { output?: string; json: boolean; max: number; + /** Sample the CPU to name blocking code (default on) */ + profile: boolean; /** Ms to wait for the app to listen before giving up */ startTimeoutMs: number; } @@ -42,7 +46,9 @@ export const RUN_USAGE = ` traceperf run [app args] [options] --warmup 3 untimed requests per path first (cold start), 0 for none --html out.html write an HTML report --output f.jsonl keep the raw request trees - --json print stats and findings as JSON`; + --json print stats and findings as JSON + --no-profile don't sample the CPU (blocking code is then named + only by its tracked call)`; function parseDuration(value: string | undefined): number | undefined { const m = /^(\d+(?:\.\d+)?)(ms|s|m)?$/.exec(value || ''); @@ -55,7 +61,7 @@ function parseDuration(value: string | undefined): number | undefined { export function parseRunArgs(argv: string[]): RunArgs | string { const args: RunArgs = { command: [], paths: [], concurrency: 10, durationMs: 5000, host: '127.0.0.1', - method: 'GET', warmup: 3, json: false, max: 10, startTimeoutMs: 15000, + method: 'GET', warmup: 3, json: false, profile: true, max: 10, startTimeoutMs: 15000, }; const num = (name: string, v: string | undefined): number | string => { const n = Number(v); @@ -108,6 +114,7 @@ export function parseRunArgs(argv: string[]): RunArgs | string { break; } case '--json': args.json = true; break; + case '--no-profile': args.profile = false; break; default: // Our options can come before or after the app; anything else after // the app is the app's own argument (use -- to pass everything as is) @@ -124,21 +131,27 @@ export interface LoadResult { errors: number; statuses: Record; durationMs: number; + /** Client-side latency per path (ms), as the load generator saw it */ + latency: Record; } /** Send concurrent requests until the duration or request count is reached */ export function sendLoad(http: any, args: RunArgs, port: number): Promise { const agent = new http.Agent({ keepAlive: true, maxSockets: args.concurrency }); - const result: LoadResult = { requests: 0, errors: 0, statuses: {}, durationMs: 0 }; + const result: LoadResult = { requests: 0, errors: 0, statuses: {}, durationMs: 0, latency: {} }; const start = Date.now(); const deadline = start + args.durationMs; let issued = 0; const more = () => (args.requests !== undefined ? issued < args.requests : Date.now() < deadline); const one = (path: string) => new Promise(resolve => { + const sent = Date.now(); const req = http.request({ host: args.host, port, path, method: args.method, agent }, (res: any) => { result.statuses[res.statusCode] = (result.statuses[res.statusCode] || 0) + 1; res.resume(); - res.on('end', resolve); + res.on('end', () => { + (result.latency[path] = result.latency[path] || []).push(Date.now() - sent); + resolve(); + }); res.on('error', resolve); }); req.setTimeout(30000, () => req.destroy(new Error('timeout'))); @@ -162,19 +175,59 @@ export function sendLoad(http: any, args: RunArgs, port: number): Promise { + if (values.length === 0) return 0; + const sorted = [...values].sort((a, b) => a - b); + return sorted[Math.min(sorted.length - 1, Math.floor((p / 100) * sorted.length))]; +}; + +/** + * Time clients waited that the app never saw: a request that arrives while + * the event loop is blocked waits in the socket before its handler starts, + * so the server-side duration misses it. Compares the load generator's + * latency with the request trees, per path. + */ +export function queueFindings(load: LoadResult, trees: Array<{ label: string; duration: number }>, method: string): Finding[] { + const findings: Finding[] = []; + for (const [path, latencies] of Object.entries(load.latency)) { + const label = `${method} ${normalizePath(path)}`; + const server = trees.filter(t => t.label === label).map(t => t.duration); + if (server.length === 0 || latencies.length === 0) continue; + const client50 = percentile(latencies, 50); + const server50 = percentile(server, 50); + const gap = client50 - server50; + if (gap >= 10 && gap >= 0.5 * client50) { + findings.push({ + kind: 'blocked', + root: label, + ms: gap * latencies.length, + message: `${label} took ${server50.toFixed(1)} ms in the app (median) but clients waited ${client50.toFixed(0)} ms: requests sat queued until the event loop was free (see blocking code above)`, + }); + } + } + return findings; +} + export interface RunSummary { stats: string; findings: Finding[]; trees: number; } -/** Stats and findings from the JSON lines the app wrote */ -export function summarise(text: string, deps: { report: (t: string, o: any) => string; parseTrees: (t: string) => any[] }, max = 10): RunSummary { +/** Stats and findings from the JSON lines the app wrote (and its blocking profiles) */ +export function summarise( + text: string, + deps: { report: (t: string, o: any) => string; parseTrees: (t: string) => any[] }, + max = 10, + profiles: BlockingProfileEntry[] = [], + cwd?: string, +): RunSummary { const trees = deps.parseTrees(text); + const hotspots = profiles.length ? blockingHotspots(profiles, { cwd }) : undefined; return { trees: trees.length, stats: trees.length ? deps.report(text, { top: 5 }) : '', - findings: explain(trees, { max }), + findings: explain(trees, { max, hotspots }), }; } @@ -200,6 +253,7 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise { const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'traceperf-run-')); const output = args.output ? path.resolve(args.output) : path.join(dir, 'calls.jsonl'); const readyFile = path.join(dir, 'port'); + const profileFile = path.join(dir, 'profiles.jsonl'); if (args.output) fs.writeFileSync(output, ''); const env: Record = { ...process.env, @@ -207,6 +261,7 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise { TRACEPERF_SILENT: '1', TRACEPERF_SUMMARY: '0', TRACEPERF_READY_FILE: readyFile, + ...(args.profile ? { TRACEPERF_PROFILE_BLOCKING: '1', TRACEPERF_PROFILE_OUTPUT: profileFile } : {}), } as Record; const [cmd, ...cmdArgs] = args.command; const quoted = JSON.stringify(deps.registerPath); @@ -280,7 +335,21 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise { } catch { text = ''; } - const summary = summarise(text, deps, args.max); + const profiles: BlockingProfileEntry[] = []; + try { + for (const line of fs.readFileSync(profileFile, 'utf8').split('\n')) { + if (line.trim()) profiles.push(JSON.parse(line)); + } + } catch { + // no profiles: --no-profile, no inspector, or nothing blocked + } + const summary = summarise(text, deps, args.max, profiles, process.cwd()); + if (load) { + const queued = queueFindings(load, deps.parseTrees(text), args.method); + // After blocking findings, which explain them + const after = summary.findings.filter(f => f.kind === 'error' || f.kind === 'blocking').length; + 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(' ')}` })); }