diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 0c25dae..0585434 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -52,6 +52,8 @@ jobs: - name: Type-check sources and tests run: npm run typecheck - run: npm test + - name: Score traceperf run on 20 apps (planted problems found, no false alarms) + run: npm run eval - name: Package lint (publint + are-the-types-wrong) run: npm run lint:package - name: Install the tarball into fresh CJS/ESM/TypeScript/bundler projects diff --git a/CHANGELOG.md b/CHANGELOG.md index fd52f6a..2264f58 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,14 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Fixed (found by the new evaluation set) +- `run` reported each of several `Promise.all` calls as "dominant" (each spans most of the request). Parallel calls are no longer dominant, and a dominant call must take at least 50 ms (`dominantMinMs`). +- Blocking code was reported three times: as blocking, as its own route queueing, and as the process being busy. Only the bystanders that waited behind it are listed now. +- `traceperf/auto` wrote each request tree with its own `appendFileSync`, and under load that showed up as the app's "CPU cost" (`writeFileUtf8`). Writes are batched every 20 ms. + +### Added +- `npm run eval` scores `traceperf run` on 20 apps in `examples/slow-apps`: 12 with a planted problem, 8 clean ones where the right answer is "no issues". CI fails on any missed problem or false alarm. Before these fixes: 17/17 found, 15 false alarms; after: 17/17, 0. + ### Added - **node-redis:** `instrumentNodeRedis(tp, require('redis'))` for `redis` / `@redis/client` 4 and 5: `redis GET`, `redis HSET`; MULTI and pipeline commands are tracked one by one. Auto-instrumented as the `redis` target. diff --git a/examples/slow-apps/README.md b/examples/slow-apps/README.md index 865ec95..077c02b 100644 --- a/examples/slow-apps/README.md +++ b/examples/slow-apps/README.md @@ -10,6 +10,17 @@ Each app has one planted performance problem. `traceperf run` should name it: | `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` | | `errors/` | one in three payment calls fails | `... errors/server.js --path /pay` | +| `blocking-zlib/` | `zlib.gzipSync` of 10 MB blocks `GET /health` | `... blocking-zlib/server.js --path /backup --path /health` | +| `cpu-json/` | ~15 ms of JSON work per request | `... cpu-json/server.js --path /catalogue` | +| `http-n-plus-one/` | one `fetch` per product to a pricing service | `... http-n-plus-one/server.js --path /products` | +| `parallel-n-plus-one/` | one query per user, fired with `Promise.all` | `... parallel-n-plus-one/server.js --path /team` | +| `failing-route/` | every request fails, so timings describe the error path | `... failing-route/server.js --path /invoices` | +| `flaky-dependency/` | one call in four to a dependency takes 120 ms | `... flaky-dependency/server.js --path /quote` | +| `clean-*/` (8 apps) | nothing: CRUD, batched, `Promise.all`, auth middleware, dependent queries, cached, static, fast loop | | + +Apps named `clean-*` have no problem: the right answer is "no issues", and any finding there is a false alarm. + +`npm run eval` scores every app: planted problems found, clean apps with no findings, and false alarms (findings that match no expectation). CI fails on any miss or false alarm. `allow` in `cases.json` lists findings that are true but not the point of the case (`note` says why). `cases.json` lists what each app should produce; `src/__tests__/run.test.ts` runs every app and fails if `explain` misses the planted cause. When you improve `explain`, add an app here first. diff --git a/examples/slow-apps/blocking-zlib/server.js b/examples/slow-apps/blocking-zlib/server.js new file mode 100644 index 0000000..2d78366 --- /dev/null +++ b/examples/slow-apps/blocking-zlib/server.js @@ -0,0 +1,15 @@ +// Planted cause: GET /backup gzips ~10 MB synchronously (zlib.gzipSync), +// blocking the event loop; GET /health waits behind it. +const zlib = require('zlib'); +const serve = require('../serve'); + +const data = Buffer.alloc(10 * 1024 * 1024, 'traceperf backup row\n'); + +function compressBackup() { + return zlib.gzipSync(data, { level: 9 }).length; +} + +serve({ + '/backup': async () => ({ bytes: compressBackup() }), + '/health': async () => ({ ok: true }), +}); diff --git a/examples/slow-apps/cases.json b/examples/slow-apps/cases.json index 2951abe..102faf1 100644 --- a/examples/slow-apps/cases.json +++ b/examples/slow-apps/cases.json @@ -76,12 +76,143 @@ }, { "kind": "blocking", - "includes": "hashPassword → pbkdf2Sync" + "includes": "hashPassword \u2192 pbkdf2Sync" }, { "kind": "blocked", "includes": "GET /ping took" } ] + }, + "http-n-plus-one": { + "paths": [ + "/products" + ], + "expect": [ + { + "kind": "repeated", + "includes": "10 times" + } + ], + "allow": [ + { + "kind": "busy", + "includes": "" + } + ], + "note": "10 fetch() calls per request really cost ~10-20 ms of CPU (undici), so the busy finding is true; the case is about the N+1" + }, + "parallel-n-plus-one": { + "paths": [ + "/team" + ], + "expect": [ + { + "kind": "repeated", + "includes": "SELECT * FROM avatars WHERE user_id = ? 15 times" + } + ] + }, + "blocking-zlib": { + "paths": [ + "/backup", + "/health" + ], + "expect": [ + { + "kind": "blocking", + "includes": "GET /backup" + }, + { + "kind": "blocked", + "includes": "GET /health" + } + ] + }, + "cpu-json": { + "paths": [ + "/catalogue" + ], + "expect": [ + { + "kind": [ + "blocking", + "busy" + ], + "includes": "cpu-json/server.js:9" + } + ], + "note": "~8-15 ms of JSON per request: blocking on a slow machine, CPU cost (busy) on a fast one; either is right if it names the function" + }, + "failing-route": { + "paths": [ + "/invoices" + ], + "expect": [ + { + "kind": "error", + "includes": "500" + } + ] + }, + "flaky-dependency": { + "paths": [ + "/quote" + ], + "expect": [ + { + "kind": "dominant", + "includes": "shipping.example/quote" + } + ] + }, + "clean-crud": { + "paths": [ + "/user" + ], + "expect": [] + }, + "clean-batched": { + "paths": [ + "/orders" + ], + "expect": [] + }, + "clean-parallel": { + "paths": [ + "/dashboard" + ], + "expect": [] + }, + "clean-auth-middleware": { + "paths": [ + "/profile", + "/settings" + ], + "expect": [] + }, + "clean-dependent": { + "paths": [ + "/billing" + ], + "expect": [] + }, + "clean-cached": { + "paths": [ + "/config" + ], + "expect": [] + }, + "clean-static": { + "paths": [ + "/about" + ], + "expect": [] + }, + "clean-fast-loop": { + "paths": [ + "/flags" + ], + "expect": [] } } diff --git a/examples/slow-apps/clean-auth-middleware/server.js b/examples/slow-apps/clean-auth-middleware/server.js new file mode 100644 index 0000000..7443a55 --- /dev/null +++ b/examples/slow-apps/clean-auth-middleware/server.js @@ -0,0 +1,15 @@ +// Clean: every route first loads the session (auth middleware), then does +// its own single query. The session lookup followed by the route's query is +// not "sequential calls that could run in parallel". +const serve = require('../serve'); +const { query } = require('../db'); + +const withSession = handler => async req => { + const session = await query('SELECT * FROM sessions WHERE token = ?', 6); + return handler(req, session); +}; + +serve({ + '/profile': withSession(async () => query('SELECT * FROM users WHERE id = ?', 6)), + '/settings': withSession(async () => query('SELECT * FROM settings WHERE user_id = ?', 6)), +}); diff --git a/examples/slow-apps/clean-batched/server.js b/examples/slow-apps/clean-batched/server.js new file mode 100644 index 0000000..abecb5a --- /dev/null +++ b/examples/slow-apps/clean-batched/server.js @@ -0,0 +1,12 @@ +// Clean: the fixed version of n-plus-one, two queries (orders, then all +// their items with one IN query). No issues expected. +const serve = require('../serve'); +const { query } = require('../db'); + +serve({ + '/orders': async () => { + const orders = await query('SELECT * FROM orders LIMIT 12', 5, Array.from({ length: 12 }, (_, id) => ({ id }))); + await query('SELECT * FROM items WHERE order_id IN (?)', 4); + return orders; + }, +}); diff --git a/examples/slow-apps/clean-cached/server.js b/examples/slow-apps/clean-cached/server.js new file mode 100644 index 0000000..2492971 --- /dev/null +++ b/examples/slow-apps/clean-cached/server.js @@ -0,0 +1,9 @@ +// Clean: the first request loads the config (slow), later ones read the +// in-memory cache. Warm-up absorbs the first; no issues expected. +const serve = require('../serve'); +const { query } = require('../db'); + +let cached; +serve({ + '/config': async () => (cached ??= await query('SELECT * FROM config', 80)), +}); diff --git a/examples/slow-apps/clean-crud/server.js b/examples/slow-apps/clean-crud/server.js new file mode 100644 index 0000000..4671b16 --- /dev/null +++ b/examples/slow-apps/clean-crud/server.js @@ -0,0 +1,7 @@ +// Clean: one indexed lookup per request. traceperf should report no issues. +const serve = require('../serve'); +const { query } = require('../db'); + +serve({ + '/user': async () => query('SELECT * FROM users WHERE id = ?', 2, [{ id: 1 }]), +}); diff --git a/examples/slow-apps/clean-dependent/server.js b/examples/slow-apps/clean-dependent/server.js new file mode 100644 index 0000000..b4fd2ba --- /dev/null +++ b/examples/slow-apps/clean-dependent/server.js @@ -0,0 +1,12 @@ +// Clean: two queries where the second needs the first's result (look up the +// account, then its plan). They cannot run in parallel, and both are fast. +const serve = require('../serve'); +const { query } = require('../db'); + +serve({ + '/billing': async () => { + const [account] = await query('SELECT * FROM accounts WHERE id = ?', 2, [{ planId: 3 }]); + const plan = await query('SELECT * FROM plans WHERE id = ?', 2, [{ id: account.planId }]); + return { account, plan }; + }, +}); diff --git a/examples/slow-apps/clean-fast-loop/server.js b/examples/slow-apps/clean-fast-loop/server.js new file mode 100644 index 0000000..9bda1db --- /dev/null +++ b/examples/slow-apps/clean-fast-loop/server.js @@ -0,0 +1,11 @@ +// Clean: a loop over 3 cache reads of a few microseconds each, below +// anything worth reporting as repeated. +const serve = require('../serve'); +const tp = require('traceperf'); + +const cache = new Map([['a', 1], ['b', 2], ['c', 3]]); +const get = tp.createTrackable(key => cache.get(key), { label: 'cache get' }); + +serve({ + '/flags': async () => ['a', 'b', 'c'].map(get), +}); diff --git a/examples/slow-apps/clean-parallel/server.js b/examples/slow-apps/clean-parallel/server.js new file mode 100644 index 0000000..b548b0e --- /dev/null +++ b/examples/slow-apps/clean-parallel/server.js @@ -0,0 +1,15 @@ +// Clean: the fixed version of sequential, three independent queries run +// together with Promise.all. No issues expected. +const serve = require('../serve'); +const { query } = require('../db'); + +serve({ + '/dashboard': async () => { + const [user, orders, alerts] = await Promise.all([ + query('SELECT * FROM users WHERE id = ?', 10), + query('SELECT * FROM orders WHERE user_id = ?', 10), + query('SELECT * FROM alerts WHERE user_id = ?', 10), + ]); + return { user, orders, alerts }; + }, +}); diff --git a/examples/slow-apps/clean-static/server.js b/examples/slow-apps/clean-static/server.js new file mode 100644 index 0000000..58a9509 --- /dev/null +++ b/examples/slow-apps/clean-static/server.js @@ -0,0 +1,7 @@ +// Clean: serves a small in-memory document, no I/O. No issues expected. +const serve = require('../serve'); + +const doc = { name: 'traceperf', version: 1, features: ['run', 'baseline'] }; +serve({ + '/about': async () => doc, +}); diff --git a/examples/slow-apps/cpu-json/server.js b/examples/slow-apps/cpu-json/server.js new file mode 100644 index 0000000..3ca2e49 --- /dev/null +++ b/examples/slow-apps/cpu-json/server.js @@ -0,0 +1,10 @@ +// Planted cause: every request serialises a ~1.5 MB catalogue (~8-15 ms of +// CPU each, never long enough to count as "blocking"), so throughput is +// capped by CPU, not by waiting. +const serve = require('../serve'); + +const catalogue = Array.from({ length: 6000 }, (_, i) => ({ id: i, name: `product ${i}`, tags: ['a', 'b', 'c'], price: i * 1.5, stock: { warehouse: i % 7, shelf: `s${i}` } })); + +serve({ + '/catalogue': async () => JSON.parse(JSON.stringify(catalogue)), +}); diff --git a/examples/slow-apps/failing-route/server.js b/examples/slow-apps/failing-route/server.js new file mode 100644 index 0000000..fc6aae0 --- /dev/null +++ b/examples/slow-apps/failing-route/server.js @@ -0,0 +1,12 @@ +// Planted cause: every request fails (a missing config value), so all the +// timings describe the error path, not the real work. +const serve = require('../serve'); +const { query } = require('../db'); + +serve({ + '/invoices': async () => { + await query('SELECT * FROM invoices LIMIT 20', 3); + if (!process.env.INVOICE_API_KEY) throw new Error('INVOICE_API_KEY is not set'); + return []; + }, +}); diff --git a/examples/slow-apps/flaky-dependency/server.js b/examples/slow-apps/flaky-dependency/server.js new file mode 100644 index 0000000..c5142c2 --- /dev/null +++ b/examples/slow-apps/flaky-dependency/server.js @@ -0,0 +1,13 @@ +// Planted cause: the shipping API is usually quick (5 ms) but one call in +// four takes 120 ms, so the route's tail latency comes from that one call. +const serve = require('../serve'); +const { query } = require('../db'); + +let n = 0; +serve({ + '/quote': async () => { + const cart = await query('SELECT * FROM carts WHERE id = ?', 2); + const quote = await query('GET shipping.example/quote', ++n % 4 === 0 ? 120 : 5); + return { cart, quote }; + }, +}); diff --git a/examples/slow-apps/http-n-plus-one/pricing.js b/examples/slow-apps/http-n-plus-one/pricing.js new file mode 100644 index 0000000..e4635cd --- /dev/null +++ b/examples/slow-apps/http-n-plus-one/pricing.js @@ -0,0 +1,4 @@ +// The "pricing service": a separate process, like a real downstream API +const http = require('http'); +const server = http.createServer((req, res) => setTimeout(() => res.end(JSON.stringify({ price: 10 })), 2)); +server.listen(0, '127.0.0.1', () => process.send(server.address().port)); diff --git a/examples/slow-apps/http-n-plus-one/server.js b/examples/slow-apps/http-n-plus-one/server.js new file mode 100644 index 0000000..7eadf25 --- /dev/null +++ b/examples/slow-apps/http-n-plus-one/server.js @@ -0,0 +1,21 @@ +// Planted cause: GET /products calls the pricing service once per product +// (an N+1 over HTTP) instead of one batched /prices?ids=... call. +const { fork } = require('child_process'); +const path = require('path'); +const serve = require('../serve'); + +// Not traced: started without traceperf's --require (execArgv cleared) +const pricing = fork(path.join(__dirname, 'pricing.js'), { execArgv: [], env: { ...process.env, NODE_OPTIONS: '' } }); +process.on('exit', () => pricing.kill()); +pricing.once('message', port => { + serve({ + '/products': async () => { + const products = Array.from({ length: 10 }, (_, id) => ({ id })); + for (const product of products) { + const res = await fetch(`http://127.0.0.1:${port}/price?id=${product.id}`); + product.price = (await res.json()).price; + } + return products; + }, + }); +}); diff --git a/examples/slow-apps/parallel-n-plus-one/server.js b/examples/slow-apps/parallel-n-plus-one/server.js new file mode 100644 index 0000000..7535412 --- /dev/null +++ b/examples/slow-apps/parallel-n-plus-one/server.js @@ -0,0 +1,12 @@ +// Planted cause: one query per user, but fired in parallel with Promise.all. +// Still an N+1: 15 round trips and 15 pooled connections instead of one IN query. +const serve = require('../serve'); +const { query } = require('../db'); + +serve({ + '/team': async () => { + const users = await query('SELECT * FROM users WHERE team_id = ?', 3, Array.from({ length: 15 }, (_, id) => ({ id }))); + await Promise.all(users.map(async u => { u.avatar = await query('SELECT * FROM avatars WHERE user_id = ?', 4); })); + return users; + }, +}); diff --git a/package.json b/package.json index 6dae132..057d39a 100644 --- a/package.json +++ b/package.json @@ -62,6 +62,7 @@ "build:browser": "tsc -p tsconfig.browser.json && node scripts/build-browser-global.js", "build:all": "npm run build && npm run build:esm && npm run build:browser", "test": "jest", + "eval": "node scripts/eval.js", "lint": "eslint src --ext .ts --max-warnings 0", "format": "prettier --write \"src/**/*.ts\"", "prepare": "husky || true", diff --git a/scripts/eval.js b/scripts/eval.js new file mode 100644 index 0000000..c9b79f7 --- /dev/null +++ b/scripts/eval.js @@ -0,0 +1,80 @@ +#!/usr/bin/env node +// Scores `traceperf run` on the apps in examples/slow-apps: every planted +// problem it names is a hit, every one it misses is a miss, and every finding +// that matches no expectation is a false alarm (on a clean app, all of them). +// +// npm run build && node scripts/eval.js [case-prefix] [--show] +// +// Exits 1 on any miss or false alarm, so CI keeps the score at 100%. +// Cases with "requires": "pg" run only when TRACEPERF_PG_URL is set. +const { execFile } = require('child_process'); +const fs = require('fs'); +const path = require('path'); + +const ROOT = path.join(__dirname, '..'); +const APPS = path.join(ROOT, 'examples', 'slow-apps'); +const CLI = path.join(ROOT, 'dist', 'cli.js'); +const cases = JSON.parse(fs.readFileSync(path.join(APPS, 'cases.json'), 'utf8')); + +const argv = process.argv.slice(2); +const show = argv.includes('--show'); +const only = argv.find(a => !a.startsWith('--')); + +function run(name, c) { + const args = [CLI, 'run', path.join(APPS, name, 'server.js'), ...c.paths.flatMap(p => ['--path', p]), '-d', c.duration || '1.5s', '--json', ...(c.args || [])]; + return new Promise((resolve, reject) => { + execFile(process.execPath, args, { env: { ...process.env, QUIET: '1', TRACEPERF_QUIET: '1', ...(c.env || {}) }, maxBuffer: 64 * 1024 * 1024, timeout: 120000 }, (error, stdout, stderr) => { + try { + resolve(JSON.parse(stdout)); + } catch { + reject(new Error(`${name}: no JSON output (${error ? error.message : 'exit 0'})\n${stderr}`)); + } + }); + }); +} + +// kind may be a list: either answer is right (e.g. blocking or busy, depending on machine speed) +const matches = (f, e) => [].concat(e.kind).includes(f.kind) && f.message.includes(e.includes); + +(async () => { + let hits = 0, misses = 0, falseAlarms = 0, cleanApps = 0, cleanPassed = 0; + const lines = []; + for (const [name, c] of Object.entries(cases)) { + if (only && !name.startsWith(only)) continue; + if (c.requires === 'pg' && !process.env.TRACEPERF_PG_URL) { + lines.push(`skip ${name}: needs TRACEPERF_PG_URL`); + continue; + } + let result; + try { + result = await run(name, c); + } catch (error) { + misses += c.expect.length || 1; + lines.push(`FAIL ${name}: ${error.message}`); + continue; + } + const findings = result.findings || []; + const missed = c.expect.filter(e => !findings.some(f => matches(f, e))); + // "allow" lists findings that are true but not the point of the case + const extra = findings.filter(f => !c.expect.some(e => matches(f, e)) && !(c.allow || []).some(e => matches(f, e))); + hits += c.expect.length - missed.length; + misses += missed.length; + falseAlarms += extra.length; + const clean = c.expect.length === 0; + if (clean) { + cleanApps++; + if (!extra.length) cleanPassed++; + } + const ok = !missed.length && !extra.length; + lines.push(`${ok ? 'ok ' : 'FAIL'} ${name}${clean ? ' (clean)' : ''}`); + for (const e of missed) lines.push(` missed: ${e.kind} "${e.includes}"`); + for (const f of extra) lines.push(` false alarm: ${f.kind}: ${f.message.split('\n')[0]}`); + if (show || !ok) for (const f of findings) lines.push(` | ${f.kind}: ${f.message.split('\n')[0]}`); + } + const planted = hits + misses; + console.log(lines.join('\n')); + console.log(`\nplanted problems found: ${hits}/${planted}${planted ? ` (${Math.round((100 * hits) / planted)}%)` : ''}`); + console.log(`clean apps with no findings: ${cleanPassed}/${cleanApps}`); + console.log(`false alarms: ${falseAlarms}`); + process.exit(misses || falseAlarms ? 1 : 0); +})(); diff --git a/src/__tests__/explain-auto-profile.test.ts b/src/__tests__/explain-auto-profile.test.ts index 96b7469..abf56ea 100644 --- a/src/__tests__/explain-auto-profile.test.ts +++ b/src/__tests__/explain-auto-profile.test.ts @@ -152,10 +152,10 @@ describe('explain()', () => { // ... and once in 40 requests is noise const many = [110, ...Array(39).fill(4)].map(ms => node('GET /users', 0, ms + 1, { selfDuration: 0.5, children: [node('db', 0, ms), node('auth', ms, 0.5)] })); expect(explain(many).filter(f => f.kind === 'dominant')).toEqual([]); - const slowRoots = [110, 40, 42, 41, 39].map(ms => node('GET /users', 0, ms + 1, { selfDuration: 0.5, children: [node('db', 0, ms), node('auth', ms, 0.5)] })); + const slowRoots = [110, 60, 62, 61, 59].map(ms => node('GET /users', 0, ms + 1, { selfDuration: 0.5, children: [node('db', 0, ms), node('auth', ms, 0.5)] })); const [f] = explain(slowRoots).filter(x => x.kind === 'dominant'); - expect(f.ms).toBe(41); - expect(f.message).toMatch(/\(41 ms of 42 ms\) \(seen 5 times, typical shown; worst 110 ms\)$/); + expect(f.ms).toBe(61); + expect(f.message).toMatch(/\(61 ms of 62 ms\) \(seen 5 times, typical shown; worst 110 ms\)$/); }); test('nothing to say', () => { diff --git a/src/__tests__/run.test.ts b/src/__tests__/run.test.ts index 81c8276..53c37a8 100644 --- a/src/__tests__/run.test.ts +++ b/src/__tests__/run.test.ts @@ -133,7 +133,7 @@ describe('explain on a known N+1 tree', () => { }); }); -const cases: Record }> = +const cases: Record }> = JSON.parse(fs.readFileSync(path.join(APPS, 'cases.json'), 'utf8')); describe('known-slow example apps: explain names the planted cause', () => { @@ -147,7 +147,7 @@ describe('known-slow example apps: explain names the planted cause', () => { const result = JSON.parse(out.join('\n')); expect(result.trees).toBeGreaterThan(5); for (const e of c.expect) { - const hit = result.findings.find((f: any) => f.kind === e.kind && f.message.includes(e.includes)); + const hit = result.findings.find((f: any) => ([] as string[]).concat(e.kind).includes(f.kind) && f.message.includes(e.includes)); if (!hit) throw new Error(`${name}: no ${e.kind} finding containing "${e.includes}"; got:\n${result.findings.map((f: any) => `${f.kind}: ${f.message}`).join('\n')}`); } }, 30000); diff --git a/src/core/explain.ts b/src/core/explain.ts index e78fa98..454b465 100644 --- a/src/core/explain.ts +++ b/src/core/explain.ts @@ -70,6 +70,8 @@ export interface ExplainOptions { minMs?: number; /** A child taking at least this fraction of its parent is "dominant" (default 0.6) */ dominantShare?: number; + /** A dominant call must also take at least this long (default 50 ms) */ + dominantMinMs?: number; /** Same label this many times under one parent is "repeated" (default 5) */ repeatCount?: number; /** Return at most this many findings, largest first (default 20) */ @@ -136,6 +138,7 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin const blockingMs = options.blockingMs ?? 10; const minMs = options.minMs ?? 5; const dominantShare = options.dominantShare ?? 0.6; + const dominantMinMs = options.dominantMinMs ?? 50; const repeatCount = options.repeatCount ?? 5; const findings: Array = []; @@ -289,6 +292,11 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin for (const k of root.children) { // A request that makes one call is always "mostly" that call: only say so when it is slow if (root.children.length === 1 && k.duration < 100) continue; + // A call under dominantMinMs is not worth chasing, whatever its share + if (k.duration < dominantMinMs) continue; + // Calls run in parallel (Promise.all) each span most of the request: none of them "dominates" + const parallel = root.children.some(o => o !== k && overlap(k.startTime, k.startTime + k.duration, o.startTime, o.startTime + o.duration) >= 0.5 * k.duration); + if (parallel) continue; if (k.duration >= minMs && k.duration >= dominantShare * root.duration) { const waited = blockers .filter(b => b.root !== i) diff --git a/src/register.ts b/src/register.ts index f55a7bf..a5e0c9f 100644 --- a/src/register.ts +++ b/src/register.ts @@ -52,7 +52,26 @@ if (flag(env.TRACEPERF_ENABLED, true) && !g[AUTO_KEY]) { ...(sampleRate !== undefined ? { sampleRate } : {}), }); if (output && fs) { - tracePerf.use(jsonLinesExporter(line => fs.appendFileSync(output, line + '\n'))); + // Batched: one appendFileSync per request (open, write, close) cost more CPU than + // many apps' own handlers and showed up as their "CPU cost" under load + let pending: string[] = []; + const flush = () => { + if (!pending.length) return; + const text = pending.join(''); + pending = []; + try { + fs.appendFileSync(output, text); + } catch { + // reporting must never break the app + } + }; + const timer = setInterval(flush, 20); + if (typeof timer.unref === 'function') timer.unref(); + process.on('exit', flush); + tracePerf.use(jsonLinesExporter(line => { + pending.push(line + '\n'); + if (pending.length >= 500) flush(); + })); } // Keep the most recent trees for the exit summary diff --git a/src/run.ts b/src/run.ts index f7bedc2..6608205 100644 --- a/src/run.ts +++ b/src/run.ts @@ -329,6 +329,12 @@ export function busyFinding(samples: LoadSample[], load: LoadResult, window: { s }; } +/** The function a busy finding names first ("CPU time went to: X (file) 83%") */ +function busyTop(f: Finding): string | undefined { + const m = /CPU time went to: ([^,(]+?)(?: \(|,| \d+%)/.exec(f.message); + return m ? m[1].trim() : undefined; +} + const STATUS_TEXT: Record = { 400: 'Bad Request', 401: 'Unauthorized', 403: 'Forbidden', 404: 'Not Found', 405: 'Method Not Allowed', 429: 'Too Many Requests', 500: 'Internal Server Error', 502: 'Bad Gateway', 503: 'Service Unavailable', @@ -643,7 +649,15 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise { const cost = loadWindow ? loadCost(samples, load, loadWindow) : undefined; // Queueing with nothing blocking and cheap requests: the load test filled the process, as it does if (!blocked && cost && cost.perRequest < 5) queued = []; - if (busy) { + if (blocked) { + // A route that itself blocks, or whose wait an explain "blocked" finding already names, + // needs no second line saying it queued: keep only the innocent bystanders + const blocking = summary.findings.filter(f => f.kind === 'blocking' || f.kind === 'blocked').map(f => f.message); + queued = queued.filter(q => !blocking.some(m => m.startsWith(`${q.root} `))); + } + // Busy because of the blocking code already reported: the same cause twice + const busyIsBlocking = !!busy && blocked && summary.findings.some(f => f.kind === 'blocking' && busyTop(busy) !== undefined && f.message.includes(busyTop(busy) as string)); + if (busy && !busyIsBlocking) { // Saturated: "time outside tracked calls" is a symptom of it, not a cause // ... and so is a call that is slow only in the tail (it waited for the CPU) const tailOnly = (f: Finding) => {