Evaluation set (20 apps) and the false alarms it found

.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

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.
 

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.
 

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 }),
+});

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": []
   }
 }

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)),
+});

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;
+  },
+});

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)),
+});

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 }]),
+});

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 };
+  },
+});

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),
+});

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 };
+  },
+});

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,
+});

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)),
+});

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 [];
+  },
+});

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 };
+  },
+});

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));

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;
+    },
+  });
+});

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;
+  },
+});

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",