Name blocking code that isn't tracked

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

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`
 

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.

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` |

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

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"
+      }
+    ]
   }
 }

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