diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 86d56df..9c6cb88 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -94,9 +94,15 @@ traceperf/ - Include examples for new features - Keep the README up to date +## What to work on + +The focus is `traceperf run`, `explain`, `traceperf/auto`, the driver integrations and the CI baseline. Changes to findings need a case in `examples/slow-apps` (a planted problem, or a `clean-*` app where the right answer is "no issues") and `npm run eval` must stay at every problem found and no false alarms. Driver changes need a check in `test/compat` that runs old and new majors against real servers. + +The browser build, other runtimes, exporters and the decorator/logging APIs are in maintenance: bug fixes welcome, new features only when an issue asks for them. + ## Release Process -The maintainers will handle the release process, including: +At most one release a week (regression fixes excepted), batching what has landed. The maintainers will handle the release process, including: 1. Updating the version number 2. Updating the changelog diff --git a/README.md b/README.md index 4bade7d..e8be805 100644 --- a/README.md +++ b/README.md @@ -1,11 +1,21 @@ # TracePerf -**See where the time goes in your code.** It prints the call tree while you develop, keeps cheap per-function statistics in production, and exports to Perfetto or OpenTelemetry when you need more. +**Find out why your Node.js API is slow, and stop pull requests that make it slower.** One command starts your app, sends it traffic, and names the cause: N+1 queries, awaits that could run in parallel, code blocking the event loop, a full connection pool, a missing index. No code changes. [![npm version](https://img.shields.io/npm/v/traceperf.svg)](https://www.npmjs.com/package/traceperf) [![License: MIT](https://img.shields.io/badge/License-MIT-blue.svg)](https://opensource.org/licenses/MIT) -![traceperf output: a request's call tree with self and sync time, a blocked-event-loop warning and a stats table](docs/assets/terminal.svg) +![traceperf run finds an N+1 query with the fix to make, and reports no issues once it is fixed](docs/assets/demo.svg) + +```bash +npx traceperf run server.js --path /orders --path /users/1 +``` + +Then keep it fixed: [`--baseline`](#in-ci-fail-a-pr-that-adds-queries) fails a pull request when a route starts making more queries per request. It compares counts, not timings, so it gives the same answer on any CI machine, and [the GitHub Action](#in-ci-fail-a-pr-that-adds-queries) comments what changed. + +**How well it works:** `npm run eval` scores it on 24 small apps, 14 with a planted problem and 10 clean ones where the right answer is "no issues". CI requires every problem found and no false alarms. It has also been checked on public apps (Express, NestJS and Fastify, with Prisma, Mongoose, TypeORM and Drizzle). The thresholds are tuned on those apps, so if it gets your app wrong, [open an issue](https://github.com/thelastbackspace/traceperf/issues) with the output. + +Underneath is a tracking library you can also use directly: - **No code changes needed.** `node --require traceperf/auto app.js` tracks every request, outgoing call and database query, and tells you why slow requests were slow when the process exits. - **Explains, not just measures.** `traceperf explain` points out blocked event loops (and which function blocked it), awaits that could run in parallel and N+1 queries. @@ -29,6 +39,8 @@ npm install traceperf ## Quick start +![traceperf output: a request's call tree with self and sync time, a blocked-event-loop warning and a stats table](docs/assets/terminal.svg) + ```javascript const { createTracePerf } = require('traceperf'); const tp = createTracePerf(); @@ -819,6 +831,14 @@ Use a sampling profiler (clinic.js, `--cpu-prof`) when you don't know where to l - `explain()` only sees tracked calls: it can say a request was delayed by blocking code, but names the function only if that function is tracked. `profileSlowCalls` finds untracked hot code. - In the default OpenTelemetry mode, spans are created when the top-level call finishes. Use `{ live: true }` if other instrumentation's spans should nest inside traceperf's. - `fetch` instrumentation times the request until the response headers arrive, not the time spent reading the body. +- The missing-index check is Postgres only (MySQL's EXPLAIN is not read yet) and needs realistic data: on a small test database Postgres scans tables on purpose. Pool waits are tracked for `pg` and `mysql2` pools, not Prisma's or Mongoose's own pools. +- `traceperf run`'s findings come from synthetic traffic to the paths you give, on one process. They tell you what those requests do, not what production traffic does; the evaluation apps are small and synthetic too. + +## Project focus + +New work goes into `traceperf run`, `explain`, `traceperf/auto`, the driver integrations and the CI baseline: finding why a Node API is slow and keeping it fixed. The rest (the browser build, Bun/Deno/Workers/Edge support, exporters, the decorator and logging APIs) is kept working and tested on every change, but gets no new features unless someone asks for one in an issue. + +Releases: at most one a week, batching what has landed, except fixes for regressions. The changelog lists every change. ## Examples diff --git a/docs/assets/demo.svg b/docs/assets/demo.svg new file mode 100644 index 0000000..9184c42 --- /dev/null +++ b/docs/assets/demo.svg @@ -0,0 +1,21 @@ + + + + + $ npx traceperf run server.js --path /orders + load: 365 requests in 2.1 s (170/s), 365× 200 + + Why it was slow: + 🔁 GET /orders called SELECT * FROM items WHERE order_id = ? 12 times (39 ms total); batching + them into one call may help (N+1 pattern) (seen 10 times, typical shown) + fix: load them in one query: WHERE id IN (...) (or = ANY($1) in Postgres), or your ORM's + include/join; then match results in memory + + # after replacing the per-order query with one WHERE order_id IN (...) + $ npx traceperf run server.js --path /orders + load: 1417 requests in 2.0 s (704/s), 1417× 200 + + Why it was slow: + No issues found: nothing blocked, repeated, or ran sequentially in a way worth changing. + + diff --git a/scripts/render-demo.js b/scripts/render-demo.js new file mode 100644 index 0000000..76682eb --- /dev/null +++ b/scripts/render-demo.js @@ -0,0 +1,82 @@ +#!/usr/bin/env node +/** + * Render the README demo: `traceperf run` on the N+1 example app, then on + * its fixed version, as an SVG terminal. Both outputs come from running the + * real CLI, so the image shows what traceperf actually prints. + * + * npm run build && node scripts/render-demo.js + * + * Writes docs/assets/demo.svg. + */ +'use strict'; +const { execFileSync } = require('child_process'); +const fs = require('fs'); +const path = require('path'); + +const ROOT = path.resolve(__dirname, '..'); +const CLI = path.join(ROOT, 'dist', 'cli.js'); +const WIDTH = 96; + +function run(app) { + const out = execFileSync(process.execPath, [CLI, 'run', `examples/slow-apps/${app}/server.js`, '--path', '/orders', '-d', '2s'], { + cwd: ROOT, encoding: 'utf8', env: { ...process.env, QUIET: '1' }, stdio: ['ignore', 'pipe', 'pipe'], + }); + const lines = out.split('\n'); + const load = lines.find(l => l.startsWith('load:')); + const why = lines.indexOf('Why it was slow:'); + return [load, '', ...lines.slice(why).filter(l => l.trim())]; +} + +/** Wrap at WIDTH columns, continuation lines indented like the line they continue */ +function wrap(line) { + const indent = /^\s*(?:\S+ )?/.exec(line)[0].replace(/\S/g, ' ').slice(0, 3).padEnd(3); + const out = []; + let rest = line; + while ([...rest].length > WIDTH) { + const cut = rest.lastIndexOf(' ', WIDTH); + const at = cut > 20 ? cut : WIDTH; + out.push(rest.slice(0, at)); + rest = indent + rest.slice(at).trimStart(); + } + out.push(rest); + return out; +} + +const escape = s => s.replace(/&/g, '&').replace(//g, '>'); +const color = line => escape(line) + .replace(/^(\$ .*)$/, '$1') + .replace(/^(# .*)$/, '$1') + .replace(/(N\+1 pattern)/, '$1') + .replace(/^(\s+fix:)/, '$1') + .replace(/(No issues found)/, '$1') + .replace(/^(load: .*)$/, '$1'); + +const before = run('n-plus-one'); +const after = run('clean-batched'); +const lines = [ + '$ npx traceperf run server.js --path /orders', + ...before, + '', + '# after replacing the per-order query with one WHERE order_id IN (...)', + '$ npx traceperf run server.js --path /orders', + ...after, +].flatMap(wrap); + +const charW = 8.4; +const lineH = 20; +const pad = 20; +const top = 44; +const width = Math.ceil(WIDTH * charW + pad * 2); +const height = top + lines.length * lineH + pad; +const text = lines.map((l, i) => ` ${color(l)}`).join('\n'); +const svg = ` + + + +${text} + + +`; +const out = path.join(ROOT, 'docs', 'assets', 'demo.svg'); +fs.writeFileSync(out, svg); +console.log(`wrote ${path.relative(process.cwd(), out)} (${lines.length} lines)`);