Merge pull request #17 from thelastbackspace/feat/cpu-advice

Library-specific CPU advice; README for run's new features

Author: thelastbackspace

CHANGELOG.md

@@ -8,6 +8,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 ## [Unreleased]
 
 ### Added
+- **What to do about the CPU, per library:** the CPU-cost finding now matches its hottest functions against known library costs and says what helps: Mongoose (`.lean()`), TypeORM (fewer relations, `getRawMany()`), Sequelize (`raw: true`), Prisma, Express's per-response ETag (`app.set('etag', false)`), class-transformer / class-validator, large JSON responses, password hashing, logging, garbage collection. Found on the NestJS app: 26% of its CPU was Express's `res.send`, 40% TypeORM query building.
 - **`mysql` (the classic driver)**, used by TypeORM, Knex and many older apps: `instrumentMysql(tp, require('mysql'))`, auto-detected. Connections and pools (`pool.query` includes waiting for a free connection, and failures to get one), labelled like mysql2: `mysql SELECT users`.
 - **`traceperf run` measures in two phases.** After the warm-up it sends `--probe` requests per path (default 10) one at a time, then the concurrent load. Per-request findings (a dominant call, sequential awaits, N+1) come from the one-at-a-time phase: under load every await also waits for the busy event loop, so a 1 ms query on a 60-row table measured 12 ms and was reported as "check this query's plan". Blocking, queueing, errors and CPU cost still come from the load.
 - **Failed responses are called out first:** "2117 of 2117 responses failed (most: 2117× 401 Unauthorized), so the timings below describe error responses", with a hint (`-H` for 401/403, `--path` for 404). An expired token used to give "no issues found".

README.md

@@ -85,9 +85,22 @@ The database was fast; `buildReport` was blocking it. That only shows up when re
 
 - **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.
+- **What each request costs:** `run` measures how busy the event loop was during the load and where the CPU went. When requests are expensive it says what that means and what helps, for the libraries it recognises (Mongoose, TypeORM, Sequelize, Prisma, Express, class-validator…):
+
+  ```
+  🔥 Each request keeps the event loop busy ~10.7 ms, so one process tops out near 94 requests/s … CPU time went to:
+     getProperty (node_modules/mongoose/lib/helpers/get.js:63) 19%, cloneObject (…/clone.js:120) 17%, (garbage collection) 15%
+     fix: Mongoose is building full documents: add .lean() to read-only queries … and .select() only the fields you send
+  ```
+- **Timings you can trust:** after the warm-up, `run` sends a few requests one at a time (`--probe`) and takes the per-request findings (a call taking most of a request, sequential awaits, N+1) from those. Under concurrent load every `await` also waits for the busy event loop, which makes fast queries look slow.
+- **Wrong setup is said first:** "2117 of 2117 responses failed (most: 401 Unauthorized)…" instead of timings of error pages.
+
+Checked on real apps, not only on the planted ones: Prisma's REST example, the RealWorld API (Express + Prisma), an Express + Mongoose boilerplate and a NestJS + TypeORM app.
 
 - `--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).
+- `-H "Authorization: Bearer $TOKEN"` (repeatable): request headers, for APIs behind a login.
+- `--probe 10`: requests per path sent one at a time before the load (0 for none).
 - `--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.
@@ -99,7 +112,7 @@ The same naming works without `run`: `TRACEPERF_PROFILE_BLOCKING=1 node --requir
 
 ## No code changes: `traceperf/auto`
 
-Start your app with traceperf preloaded. Every incoming HTTP request becomes a tree, with the outgoing `http`/`fetch` calls and the `pg`, `mysql2`, MongoDB/Mongoose, `ioredis`, Prisma and `better-sqlite3` queries it made nested under it (Drizzle runs on these drivers, so its queries show up too):
+Start your app with traceperf preloaded. Every incoming HTTP request becomes a tree, with the outgoing `http`/`fetch` calls and the `pg`, `mysql2`, `mysql`, MongoDB/Mongoose, `ioredis`, Prisma and `better-sqlite3` queries it made nested under it (Drizzle runs on these drivers, so its queries show up too):
 
 <!-- docs:skip -->
 ```bash
@@ -203,10 +216,11 @@ Ready-made helpers for popular clients. Pass the module you already use; tracepe
 
 <!-- docs:skip -->
 ```javascript
-const { instrumentPg, instrumentMysql2, instrumentMongo, instrumentRedis, instrumentAwsClient, instrumentPrisma, instrumentBetterSqlite3, prismaExtension } = require('traceperf');
+const { instrumentPg, instrumentMysql2, instrumentMysql, instrumentMongo, instrumentRedis, instrumentAwsClient, instrumentPrisma, instrumentBetterSqlite3, prismaExtension } = require('traceperf');
 
 instrumentPg(tp, require('pg'));                    // "pg SELECT users" (Pool.query included)
 instrumentMysql2(tp, require('mysql2'));            // "mysql UPDATE orders" (callback and promise APIs)
+instrumentMysql(tp, require('mysql'));              // the classic driver: connections and pools
 instrumentMongo(tp, require('mongodb'));            // "mongo find users", "mongo insertOne users"
 instrumentMongo(tp, require('mongoose').mongo);     // Mongoose uses its own copy of the driver
 instrumentRedis(tp, require('ioredis'));            // "redis GET"

src/__tests__/prometheus.test.ts

@@ -16,17 +16,18 @@ function parse(text: string): Record<string, number> {
 }
 
 test('histogram buckets, sum, count and errors per label', () => {
-  const prom = prometheusExporter({ buckets: [0.005, 0.05] });
+  const prom = prometheusExporter({ buckets: [0.02, 0.2] });
   const tp = createTracePerf({ silent: true, trackMemory: false, plugins: [prom] });
   const query = tp.createTrackable((ms: number) => busyWait(ms), { label: 'db.query' });
-  tp.track(() => { query(0); query(20); }, { label: 'GET /x' });
+  // A call doing nothing must land in the first bucket even on a busy machine (wide margin)
+  tp.track(() => { query(0); query(40); }, { label: 'GET /x' });
   expect(() => tp.track(() => { throw new Error('x'); }, { label: 'job "a"\nb' })).toThrow();
   const m = parse(prom.metrics());
-  expect(m['traceperf_call_duration_seconds_bucket{name="db.query",le="0.005"}']).toBe(1);
-  expect(m['traceperf_call_duration_seconds_bucket{name="db.query",le="0.05"}']).toBe(2);
+  expect(m['traceperf_call_duration_seconds_bucket{name="db.query",le="0.02"}']).toBe(1);
+  expect(m['traceperf_call_duration_seconds_bucket{name="db.query",le="0.2"}']).toBe(2);
   expect(m['traceperf_call_duration_seconds_bucket{name="db.query",le="+Inf"}']).toBe(2);
   expect(m['traceperf_call_duration_seconds_count{name="db.query"}']).toBe(2);
-  expect(m['traceperf_call_duration_seconds_sum{name="db.query"}']).toBeGreaterThanOrEqual(0.019);
+  expect(m['traceperf_call_duration_seconds_sum{name="db.query"}']).toBeGreaterThanOrEqual(0.039);
   expect(m['traceperf_call_duration_seconds_count{name="GET /x"}']).toBe(1);
   expect(m['traceperf_call_errors_total{name="job \\"a\\"\\nb"}']).toBe(1);
   expect(prom.metrics()).toMatch(/# TYPE traceperf_call_duration_seconds histogram/);

src/__tests__/run.test.ts

@@ -274,6 +274,24 @@ describe('statusFinding', () => {
   });
 });
 
+describe('cpuAdvice', () => {
+  const { cpuAdvice } = jest.requireActual('../run');
+  const spot = (functionName: string, location: string, ms: number) => ({ functionName, location, ms });
+  it('names what to do for the libraries using the CPU', () => {
+    const nest = [
+      spot('send → end', 'node_modules/express/lib/response.js:170', 26),
+      spot('DriverUtils.buildAlias', 'node_modules/typeorm/driver/DriverUtils.js:100', 17),
+      spot('escapeRegExp', 'node_modules/typeorm/query-builder/QueryBuilder.js:445', 10),
+      spot('render', 'src/view.js:3', 47),
+    ];
+    const advice = cpuAdvice(nest, 100);
+    expect(advice).toMatch(/^Express computes an ETag .*; TypeORM spends CPU .*; beyond that, run more processes/);
+    expect(advice.match(/TypeORM/g)).toHaveLength(1);
+    // Under 10% of the time: not worth a library-specific hint
+    expect(cpuAdvice([spot('x', 'node_modules/mongoose/lib/document.js:1', 5), spot('y', 'src/a.js:1', 95)], 100)).toMatch(/^cut the CPU each request needs/);
+  });
+});
+
 describe('busyFinding', () => {
   const { busyFinding } = jest.requireActual('../run');
   const load = { requests: 400, errors: 0, statuses: {}, durationMs: 4000, latency: {} };

src/run.ts

@@ -267,6 +267,32 @@ export function loadCost(samples: LoadSample[], load: LoadResult, window: { star
   return { busy: active / (active + idle), perRequest: rate > 0 ? (activeRate * 1000) / rate : 0, rate };
 }
 
+/** Known CPU costs of popular libraries, matched against the hottest functions, and what to do */
+const CPU_ADVICE: Array<{ test: RegExp; advice: string }> = [
+  { test: /mongoose[\\/]lib[\\/](document|helpers|schema|types)/, advice: 'Mongoose is building full documents: add .lean() to read-only queries (plain objects, often several times less CPU) and .select() only the fields you send' },
+  { test: /typeorm[\\/](query-builder|driver[\\/]DriverUtils|metadata|entity-manager|persistence)/, advice: 'TypeORM spends CPU building queries and mapping rows to entities: on hot read paths load fewer relations and columns, or use getRawMany() / a raw query' },
+  { test: /sequelize[\\/]lib[\\/](model|instance|utils|dialects)/, advice: 'Sequelize is building model instances: use raw: true on hot read queries and limit attributes / includes' },
+  { test: /@prisma[\\/]client[\\/]runtime/, advice: 'Prisma\'s client is serialising queries and results: select only the fields you send and avoid deep include trees on hot paths' },
+  { test: /express[\\/]lib[\\/]response\.js|[\\/]etag[\\/]/, advice: "Express computes an ETag (a hash of the body) for every response: app.set('etag', false) if clients don't send conditional requests, and send smaller bodies" },
+  { test: /class-transformer|class-validator/, advice: 'class-transformer / class-validator run on every request (NestJS pipes and serialisers): skip them on hot read routes or validate less deeply' },
+  { test: /JSON\.stringify|fast-json-stringify|safe-stable-stringify/, advice: 'serialising large responses: paginate, send fewer fields, or use a schema-based serialiser (fast-json-stringify)' },
+  { test: /bcrypt|argon2|scrypt|pbkdf2/i, advice: 'password hashing is CPU by design: keep it to login routes, use the async API, and do not hash per request' },
+  { test: /winston|pino|morgan|debug[\\/]src|console/, advice: 'logging costs CPU per request: log less on hot routes, avoid pretty formatting in production, prefer pino' },
+  { test: /\(garbage collection\)/, advice: 'much of it is garbage collection: allocate less per request (smaller objects and arrays, no needless copies)' },
+];
+
+/** Advice for the hottest functions (those with at least 10% of the CPU time), then the general fix */
+export function cpuAdvice(spots: Array<{ functionName: string; location: string; ms: number }>, total: number): string {
+  const hints: string[] = [];
+  for (const h of spots) {
+    if (h.ms < 0.1 * total || hints.length >= 2) continue;
+    const rule = CPU_ADVICE.find(r => r.test.test(`${h.functionName} ${h.location}`));
+    if (rule && !hints.includes(rule.advice)) hints.push(rule.advice);
+  }
+  const general = 'run more processes (cluster or more instances) so requests stop waiting for each other';
+  return hints.length ? `${hints.join('; ')}; beyond that, ${general}` : `cut the CPU each request needs (start with the functions above), or ${general}`;
+}
+
 /**
  * The app was saturated *and* each request is expensive (5 ms of CPU or
  * more, a ceiling near 200/s per process): a load test saturates any one
@@ -283,10 +309,7 @@ export function busyFinding(samples: LoadSample[], load: LoadResult, window: { s
   const shown = spots.filter(h => h.ms >= 0.04 * total).slice(0, 4)
     .map(h => `${h.functionName}${h.location ? ` (${h.location})` : ''} ${Math.round((h.ms / Math.max(total, 1e-9)) * 100)}%`);
   const where = shown.length ? `; CPU time went to: ${shown.join(', ')}` : '';
-  const mongooseDocs = spots.slice(0, 5).some(h => /mongoose[\\/]lib[\\/](document|helpers|schema)/.test(h.location));
-  const fix = mongooseDocs
-    ? 'Mongoose is building full documents: add .lean() to read-only queries (plain objects, often several times less CPU) and select only the fields you send; beyond that, run more processes (cluster or more instances)'
-    : 'cut the CPU each request needs (start with the functions above), or run more processes (cluster or more instances) so requests stop waiting for each other';
+  const fix = cpuAdvice(spots, total);
   return {
     kind: 'busy',
     root: 'process',