run: probe phase for undistorted per-request findings; failed-response warning

CHANGELOG.md

@@ -7,6 +7,13 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+### Added
+- **`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".
+
+### Changed (from running it on a NestJS 7 + TypeORM app)
+- A finding seen once in 10 or more requests is an outlier, not a pattern (was: only under 5% of 20+).
+
 ## [1.6.0] - 2026-11-06
 
 (Includes 1.5.1, which was tagged but never published.)

src/__tests__/explain-auto-profile.test.ts

@@ -142,10 +142,13 @@ describe('explain()', () => {
     // A request that makes one call is always mostly that call: not worth saying unless it is slow
     expect(explain([node('GET /a', 0, 21, { selfDuration: 1, children: [node('db', 0, 20)] })])).toEqual([]);
     expect(explain([node('GET /a', 0, 151, { selfDuration: 1, children: [node('db', 0, 150)] })])[0].kind).toBe('dominant');
-    // 9 requests where the query is 4 ms of 5 ms, one where the first connection made it 110 ms
-    const roots = [110, ...Array(9).fill(4)].map(ms => node('GET /users', 0, ms + 1, { selfDuration: 0.5, children: [node('db', 0, ms), node('auth', ms, 0.5)] }));
+    // 7 requests where the query is 4 ms of 5 ms, one where the first connection made it 110 ms
+    const roots = [110, ...Array(7).fill(4)].map(ms => node('GET /users', 0, ms + 1, { selfDuration: 0.5, children: [node('db', 0, ms), node('auth', ms, 0.5)] }));
     const [once] = explain(roots).filter(f => f.kind === 'dominant');
-    expect(once.message).toMatch(/\(in 1 of 10 GET \/users\)$/);
+    expect(once.message).toMatch(/\(in 1 of 8 GET \/users\)$/);
+    // once in 10 or more is an outlier
+    const ten = [110, ...Array(9).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(ten).filter(f => f.kind === 'dominant')).toEqual([]);
     // ... 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([]);

src/__tests__/run.test.ts

@@ -159,7 +159,7 @@ describe('runApp', () => {
     const html = path.join(dir, 'r.html');
     const output = path.join(dir, 'calls.jsonl');
     const out: string[] = [];
-    const args = parseRunArgs([path.join(APPS, 'sequential', 'server.js'), '--path', '/dashboard', '-n', '20', '--html', html, '--output', output, '--warmup', '0']) as RunArgs;
+    const args = parseRunArgs([path.join(APPS, 'sequential', 'server.js'), '--path', '/dashboard', '-n', '20', '--html', html, '--output', output, '--warmup', '0', '--probe', '0']) as RunArgs;
     expect(await runApp(args, deps(out))).toBe(0);
     const text = out.join('\n');
     expect(text).toContain('load: 20 requests');
@@ -259,6 +259,21 @@ describe('naming blocking code from CPU profiles', () => {
   });
 });
 
+describe('statusFinding', () => {
+  const { statusFinding } = jest.requireActual('../run');
+  const load = (statuses: Record<string, number>, errors = 0) => ({ requests: 10, errors, statuses, durationMs: 1, latency: {} });
+  it('warns when most responses failed, with a hint for the status', () => {
+    const f = statusFinding(load({ 401: 9, 200: 1 }));
+    expect(f.message).toBe('9 of 10 responses failed (most: 9× 401 Unauthorized), so the timings below describe error responses, not the endpoints');
+    expect(f.fix).toMatch(/-H "Authorization: Bearer \$TOKEN"/);
+    expect(statusFinding(load({ 404: 6, 200: 4 })).fix).toMatch(/--path/);
+    expect(statusFinding(load({}, 5)).message).toMatch(/most: 5× connection error/);
+  });
+  it('says nothing when most succeeded', () => {
+    expect(statusFinding(load({ 200: 8, 500: 2 }))).toBeUndefined();
+  });
+});
+
 describe('busyFinding', () => {
   const { busyFinding } = jest.requireActual('../run');
   const load = { requests: 400, errors: 0, statuses: {}, durationMs: 4000, latency: {} };

src/core/explain.ts

@@ -380,7 +380,10 @@ export function explain(roots: ExplainNode[], options: ExplainOptions = {}): Fin
     const total = rootCount.get(g.root) || 0;
     // Blocking counts per root label too; a rare but long block (a 2 s export) is still worth saying
     const scope = g.kind === 'blocking' ? Math.max(...[...g.roots].map(r => rootCount.get(r) || 0)) : total;
-    const rare = (g.roots.size === 1 || g.kind === 'blocking') && scope >= 20 && g.times / scope < 0.05 && !((g.kind === 'blocking' || g.kind === 'blocked') && g.ms >= 100);
+    // Under 5% of 20+ requests, or once in 10+: an outlier, not a pattern
+    const rare = (g.roots.size === 1 || g.kind === 'blocking') &&
+      ((scope >= 20 && g.times / scope < 0.05) || (scope >= 10 && g.times === 1)) &&
+      !((g.kind === 'blocking' || g.kind === 'blocked') && g.ms >= 100);
     if (g.ms < minMs || rare) grouped.delete(key);
     else if (g.kind !== 'blocking' && g.roots.size === 1 && total > g.times) share.set(g, `in ${g.times} of ${total} ${g.root}`);
   }

src/run.ts

@@ -21,6 +21,13 @@ export interface RunArgs {
   requests?: number;
   /** Requests per path sent before measuring (not reported), default 3 */
   warmup: number;
+  /**
+   * Requests per path sent one at a time after the warm-up (default 10, 0
+   * for none). Per-request findings (a dominant call, sequential awaits,
+   * N+1) come from these: under concurrent load every await also waits for
+   * the busy event loop, which inflates call times.
+   */
+  probe: number;
   port?: number;
   host: string;
   method: string;
@@ -47,6 +54,8 @@ export const RUN_USAGE = `  traceperf run <app.js> [app args] [options]
       --method GET     request method
       -H, --header "Name: value"   request header, repeatable (e.g. -H "Authorization: Bearer $TOKEN")
       --warmup 3       untimed requests per path first (cold start), 0 for none
+      --probe 10       requests per path sent one at a time before the load, for
+                       per-request findings with undistorted timings (0: none)
       --html out.html  write an HTML report
       --output f.jsonl keep the raw request trees
       --json           print stats and findings as JSON
@@ -64,7 +73,7 @@ function parseDuration(value: string | undefined): number | undefined {
 export function parseRunArgs(argv: string[]): RunArgs | string {
   const args: RunArgs = {
     command: [], paths: [], concurrency: 10, durationMs: 5000, host: '127.0.0.1',
-    method: 'GET', warmup: 3, json: false, profile: true, max: 10, startTimeoutMs: 15000,
+    method: 'GET', warmup: 3, probe: 10, json: false, profile: true, max: 10, startTimeoutMs: 15000,
   };
   const num = (name: string, v: string | undefined): number | string => {
     const n = Number(v);
@@ -126,6 +135,12 @@ export function parseRunArgs(argv: string[]): RunArgs | string {
       }
       case '--json': args.json = true; break;
       case '--no-profile': args.profile = false; break;
+      case '--probe': {
+        const n = Number(argv[++i]);
+        if (!(n >= 0)) return '--probe expects a number';
+        args.probe = Math.floor(n);
+        break;
+      }
       default:
         // Our options can come before or after the app; anything else after
         // the app is the app's own argument (use -- to pass everything as is)
@@ -281,6 +296,31 @@ export function busyFinding(samples: LoadSample[], load: LoadResult, window: { s
   };
 }
 
+const STATUS_TEXT: Record<string, string> = {
+  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',
+};
+
+/** Most responses were errors: the timings describe error handling, not the endpoint */
+export function statusFinding(load: LoadResult): Finding | undefined {
+  const total = Object.values(load.statuses).reduce((a, b) => a + b, 0) + load.errors;
+  const failed = Object.entries(load.statuses).filter(([s]) => Number(s) >= 400);
+  const failedCount = failed.reduce((sum, [, n]) => sum + n, 0) + load.errors;
+  if (total === 0 || failedCount < 0.5 * total) return undefined;
+  const [top, n] = failed.sort((a, b) => b[1] - a[1])[0] || ['connection error', load.errors];
+  const what = /^\d+$/.test(top) ? `${top}${STATUS_TEXT[top] ? ` ${STATUS_TEXT[top]}` : ''}` : top;
+  const hint = top === '401' || top === '403'
+    ? 'pass credentials with -H, e.g. -H "Authorization: Bearer $TOKEN" (an expired token gives this too)'
+    : top === '404' ? 'check the --path values' : 'look at the app output above for the error';
+  return {
+    kind: 'error',
+    root: 'load',
+    ms: 0,
+    message: `${failedCount} of ${total} responses failed (most: ${n}× ${what}), so the timings below describe error responses, not the endpoints`,
+    fix: hint,
+  };
+}
+
 export interface RunSummary {
   stats: string;
   findings: Finding[];
@@ -406,6 +446,16 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise<number> {
 
   let load: LoadResult | undefined;
   let skipBytes = 0;
+  let probeFrom: number | undefined;
+  const sizeNow = async (): Promise<number> => {
+    // The last trees are written just after their responses
+    await new Promise(r => setTimeout(r, 100));
+    try {
+      return fs.statSync(output).size;
+    } catch {
+      return 0;
+    }
+  };
   try {
     if (args.paths.length) {
       const port = args.port ?? (await waitForPort(fs, readyFile, () => exited, args.startTimeoutMs));
@@ -419,13 +469,13 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise<number> {
       deps.err(`traceperf: sending ${args.requests ? `${args.requests} requests` : `${args.durationMs / 1000} s of traffic`} to ${args.paths.join(', ')} on port ${port}, ${args.concurrency} at a time`);
       if (args.warmup > 0) {
         await sendLoad(deps.http, { ...args, concurrency: 1, requests: args.warmup * args.paths.length }, port);
-        // The last warm-up trees are written just after their responses
-        await new Promise(r => setTimeout(r, 100));
-        try {
-          skipBytes = fs.statSync(output).size;
-        } catch {
-          skipBytes = 0;
-        }
+        skipBytes = await sizeNow();
+      }
+      // One at a time: timings not inflated by queueing (only useful when the load is concurrent)
+      if (args.probe > 0 && args.concurrency > 1) {
+        probeFrom = skipBytes;
+        await sendLoad(deps.http, { ...args, concurrency: 1, requests: args.probe * args.paths.length }, port);
+        skipBytes = await sizeNow();
       }
       const loadStart = Date.now();
       load = await sendLoad(deps.http, args, port);
@@ -445,15 +495,18 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise<number> {
   }
 
   let text = '';
+  let probeText = '';
   try {
     const all = fs.readFileSync(output);
-    // If the cut fell inside a tree still being written, start at the next whole line
-    let from = skipBytes;
-    if (from > 0 && from < all.length && all[from - 1] !== 0x0a) {
-      const nl = all.indexOf(0x0a, from);
-      from = nl === -1 ? all.length : nl + 1;
-    }
+    // If a cut fell inside a tree still being written, move it to the next whole line
+    const align = (at: number) => {
+      if (at <= 0 || at >= all.length || all[at - 1] === 0x0a) return Math.min(Math.max(at, 0), all.length);
+      const nl = all.indexOf(0x0a, at);
+      return nl === -1 ? all.length : nl + 1;
+    };
+    const from = align(skipBytes);
     text = all.subarray(from).toString('utf8');
+    if (probeFrom !== undefined) probeText = all.subarray(align(probeFrom), from).toString('utf8');
   } catch {
     text = '';
   }
@@ -466,7 +519,15 @@ export async function runApp(args: RunArgs, deps: RunDeps): Promise<number> {
     // no profiles: --no-profile, no inspector, or nothing blocked
   }
   const summary = summarise(text, deps, args.max, profiles, process.cwd());
+  // Per-request structure from the one-at-a-time probe, where call times are not inflated by queueing
+  const STRUCTURAL = ['dominant', 'sequential', 'repeated'];
+  if (probeText.trim()) {
+    const structural = explain(deps.parseTrees(probeText), { max: args.max }).filter(f => STRUCTURAL.includes(f.kind));
+    summary.findings = [...summary.findings.filter(f => !STRUCTURAL.includes(f.kind)), ...structural].slice(0, args.max);
+  }
   if (load) {
+    const failing = statusFinding(load);
+    if (failing) summary.findings.unshift(failing);
     const blocked = summary.findings.some(f => f.kind === 'blocking');
     let queued = queueFindings(load, deps.parseTrees(text), args.method, blocked);
     let samples: LoadSample[] = [];