diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 45d4e6b..a279b27 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -10,6 +10,9 @@ concurrency: group: ${{ github.workflow }}-${{ github.ref }} cancel-in-progress: true +env: + FORCE_JAVASCRIPT_ACTIONS_TO_NODE24: "true" + jobs: test: name: Test (Node ${{ matrix.node }}) @@ -39,5 +42,5 @@ jobs: - name: Build run: npm run build - - name: Test with coverage + - name: Test with coverage gate (>=90%) run: npm run test:coverage diff --git a/.github/workflows/release.yml b/.github/workflows/release.yml index 0dd4e85..6df8486 100644 --- a/.github/workflows/release.yml +++ b/.github/workflows/release.yml @@ -6,6 +6,9 @@ on: - "v*.*.*" workflow_dispatch: +env: + FORCE_JAVASCRIPT_ACTIONS_TO_NODE24: "true" + jobs: publish-npm: name: Publish to npm diff --git a/README.md b/README.md index 25bcc45..649d34a 100644 --- a/README.md +++ b/README.md @@ -6,6 +6,10 @@ [![License: MIT](https://img.shields.io/badge/license-MIT-yellow)](./LICENSE) [![Zero Dependencies](https://img.shields.io/badge/dependencies-0-brightgreen)](./package.json) +

+ node-request-trace request timeline hero +

+ Debug any Node.js request like a timeline. `node-request-trace` shows what happened inside a request, where the time went, and which step caused the slowdown, without asking you to adopt OpenTelemetry, run a collector, or wire up a tracing backend. @@ -28,7 +32,7 @@ OpenTelemetry is powerful, standard, and absolutely worth using for large produc > Why was this request slow? -`node-request-trace` is for that moment. Add middleware, wrap important work in `trace.step()`, and immediately get request timelines, bottleneck detection, outgoing HTTP tracing, a browser dashboard, Chrome trace export, and terminal-friendly reports. +`node-request-trace` is for that moment. Add middleware, wrap important work in `trace.step()`, and immediately get request timelines, bottleneck detection, N+1 detection, outgoing HTTP tracing, a browser dashboard, and exports for terminal reports, Markdown, Chrome tracing, and Speedscope. ## The Pitch @@ -70,13 +74,17 @@ npx node-request-trace timeline http://localhost:3000 req_a1b2c3d4e5f6 ## What You Get - Request timelines with bottleneck, traced coverage, and uninstrumented gap detection. +- N+1 and duplicate-work detection within a single request. - Async context propagation through `AsyncLocalStorage`. - Manual `trace.step()` spans for database calls, service calls, queues, cache reads, and any async work. - Automatic Express, Fastify, and Koa middleware/lifecycle timing. +- Automatic database and cache instrumentation for `pg`, `mongodb`, `ioredis`, `knex`, and Prisma. - Outgoing `http`, `https`, and `fetch` tracing. -- Built-in dashboard at `/trace/ui`. -- CLI for stats, recent traces, slow traces, timeline reports, tailing, and exports. -- Chrome Trace Event export for `chrome://tracing`. +- Built-in dashboard at `/trace/ui` with waterfall, timeline, and flamegraph views. +- CLI for stats, recent traces, slow traces, timeline reports, tailing, diffing, and exports. +- Trace diffing to catch regressions between two requests. +- Optional AI explanations of why a request was slow. +- Exports for Markdown, a self-contained shareable HTML snapshot, Chrome Trace Event Format, and Speedscope. - Sampling, slow request detection, retention limits, and in-memory eviction. - Header redaction by default and no request body capture. - Zero runtime dependencies. @@ -123,7 +131,7 @@ Runnable example: [`node-actuator-lite/examples/ecosystem`](https://github.com/b npm install node-request-trace ``` -The package supports Node.js 16 and newer. It has optional peer support for Express, Fastify, and Koa, but no runtime dependencies of its own. +The package supports Node.js 16 and newer. It has optional peer support for Express, Fastify, and Koa, but no runtime dependencies of its own. AI explanations and `fetch` tracing use the global `fetch`, which is available on Node.js 18 and newer. ## Quick Start @@ -211,6 +219,7 @@ Structured reports include: - `summary.uninstrumentedDuration`: request time not explained by recorded steps. - `summary.coveragePercent`: how much of the request timeline is explained. - `summary.gaps`: idle or uninstrumented windows between steps. +- `summary.duplicates`: repeated steps, including detected N+1 patterns. - `summary.errorCount`: number of failed steps. This makes it easy to answer: @@ -218,6 +227,7 @@ This makes it easy to answer: - Did the database cause the slowdown? - Did middleware run before the handler? - How much of the request is still a blind spot? +- Am I making the same query in a loop? - Which step should I optimize first? ## Manual Instrumentation @@ -244,6 +254,42 @@ trace.init({ autoTrack: true }); Express records middleware layers. Fastify records lifecycle phases such as `onRequest`, `preParsing`, `preValidation`, `handler`, and `onSend`. Koa wraps `app.use()` middleware after `trace.instrumentKoa(app)`. +### Database and Cache Clients + +Enable `autoInstrument` to time queries from common drivers without wrapping each call in `trace.step()`. + +```js +trace.init({ autoInstrument: true }); +``` + +This patches `pg` (node-postgres), `mongodb`, and `ioredis` when they are present. Queries appear as `db` and `cache` steps with truncated, redaction-friendly labels: + +```txt +pg SELECT * FROM users WHERE id = ? 12ms [db] +mongo users.findOne 8ms [db] +redis GET 1ms [cache] +``` + +Limit which drivers are patched with the `only` list: + +```js +trace.init({ autoInstrument: { only: ["pg", "mongodb"] } }); +``` + +`knex` and Prisma are instance-based, so instrument them explicitly: + +```js +trace.instrumentKnex(knex); +trace.instrumentPrisma(prisma); +``` + +You can also toggle driver instrumentation at runtime: + +```js +trace.enableAutoInstrumentation({ only: ["pg"] }); +trace.disableAutoInstrumentation(); +``` + ### Outgoing HTTP Enable outgoing HTTP tracing to automatically capture calls made with Node's `http`, `https`, and global `fetch`. @@ -266,6 +312,79 @@ HTTP POST api.stripe.com/v1/charges 180ms [http-outgoing] HTTP GET cdn.example.com/assets 45ms [http-outgoing] ``` +## N+1 and Duplicate Detection + +`node-request-trace` groups semantically identical steps within a request so repeated work stands out. Numbers, ids, UUIDs, and quoted literals are normalized, so `SELECT ... WHERE id = 1` and `SELECT ... WHERE id = 2` count as the same pattern. + +```js +const analysis = trace.analyze(savedTrace); + +if (analysis.hasNPlusOne) { + console.log(analysis.nPlusOne); +} +``` + +The analysis reports each repeated pattern with its count, total and average duration, whether it reads as an N+1 pattern, and how much time was wasted on repetition. Detected patterns also surface in timeline reports, the dashboard, Markdown exports, and AI explanations. + +## Trace Diffing + +Compare two traces to find what changed between a fast request and a slow one, or before and after a deploy. + +```js +const diff = trace.diff(traceA, traceB); + +console.log(diff.totalDeltaMs, diff.regressed); +console.log(trace.diffToMarkdown(traceA, traceB)); +``` + +Each step is labeled `added`, `removed`, `slower`, `faster`, or `unchanged`, with per-step deltas and an overall regression flag. From the CLI: + +```bash +npx node-request-trace diff http://localhost:3000 req_aaa req_bbb +``` + +## AI Explanations + +Turn a trace into a focused, actionable explanation of why it was slow. + +```js +const text = await trace.explain(savedTrace, { + apiKey: process.env.OPENAI_API_KEY, +}); +``` + +The explanation uses any OpenAI-compatible chat completions endpoint. You supply the key, model, and base URL, so no vendor is bundled and no secrets are stored. Set `OPENAI_API_KEY` or `LLM_API_KEY`, or pass `{ apiKey }` directly. + +If you would rather not call a model, build the prompt and paste it into your own chat: + +```js +const { system, user } = trace.buildExplainPrompt(savedTrace); +``` + +From the CLI, `explain` calls the model when a key is set, and otherwise prints the prompt for you to copy: + +```bash +OPENAI_API_KEY=sk-... npx node-request-trace explain http://localhost:3000 req_abc123 +``` + +## Exports + +A trace can be exported in several formats for sharing and deeper analysis. + +```js +trace.toMarkdown(savedTrace); // GitHub-flavored markdown report +trace.toShareableHtml(savedTrace); // self-contained single-file HTML +trace.exportChromeTrace(savedTrace); // Chrome Trace Event Format object +trace.exportChromeTraceJson(savedTrace); +trace.exportSpeedscope(savedTrace); // Speedscope profile object +trace.exportSpeedscopeJson(savedTrace); +``` + +- **Markdown** is ideal for PR comments, issues, and incident notes. +- **HTML snapshot** is a single self-contained file you can open in a browser or send to a teammate. +- **Chrome Trace** loads in `chrome://tracing`. +- **Speedscope** loads at [speedscope.app](https://www.speedscope.app) for flamegraph analysis. + ## Dashboard Mount `trace.routes()` and visit `/trace/ui`. @@ -281,7 +400,8 @@ The dashboard includes: - Live feed. - Request detail view. - Waterfall, timeline, and flamegraph modes. -- Chrome trace export button. +- N+1 and duplicate-work warnings. +- Export buttons for Chrome trace, Speedscope, Markdown, and HTML snapshots. ## CLI @@ -294,10 +414,15 @@ npx node-request-trace slow http://localhost:3000 npx node-request-trace inspect http://localhost:3000 req_a1b2c3d4 npx node-request-trace timeline http://localhost:3000 req_a1b2c3d4 npx node-request-trace tail http://localhost:3000 +npx node-request-trace diff http://localhost:3000 req_aaa req_bbb +npx node-request-trace markdown http://localhost:3000 req_a1b2c3d4 +npx node-request-trace snapshot http://localhost:3000 req_a1b2c3d4 > trace.html +npx node-request-trace explain http://localhost:3000 req_a1b2c3d4 npx node-request-trace export http://localhost:3000 req_a1b2c3d4 > trace.json +npx node-request-trace speedscope http://localhost:3000 req_a1b2c3d4 > scope.json ``` -Use `timeline` when you want the fastest answer. Use `inspect` when you want the fuller detail view. Use `export` when you want to load the trace in `chrome://tracing`. +Use `timeline` when you want the fastest answer. Use `inspect` when you want the fuller detail view. Use `diff` to catch regressions, `explain` for an AI summary, and `export`, `speedscope`, `markdown`, or `snapshot` to take a trace elsewhere. `markdown` is also available as `md`. ## HTTP API @@ -310,6 +435,10 @@ Use `timeline` when you want the fastest answer. Use `inspect` when you want the | `GET /trace/:requestId` | Raw trace JSON | | `GET /trace/:requestId/timeline` | Timeline report plus ASCII rendering | | `GET /trace/:requestId/chrome` | Chrome Trace Event JSON | +| `GET /trace/:requestId/speedscope` | Speedscope profile JSON | +| `GET /trace/:requestId/markdown` | GitHub-flavored Markdown report | +| `GET /trace/:requestId/snapshot` | Self-contained shareable HTML download | +| `GET /trace/diff/:idA/:idB` | Diff between two traces | Example timeline response: @@ -345,6 +474,7 @@ trace.init({ retentionSeconds: 300, autoTrack: false, traceOutgoing: false, + autoInstrument: false, sensitiveHeaders: null, }); ``` @@ -385,6 +515,42 @@ Builds a structured timeline report. Builds an ASCII request timeline. Use `options.width` to control the chart width. +### `trace.analyze(trace)` + +Returns N+1 and duplicate-work analysis for a trace's steps. + +### `trace.diff(traceA, traceB, options)` + +Compares two traces and returns a per-step diff with an overall regression flag. + +### `trace.diffToMarkdown(traceA, traceB, options)` + +Returns the diff as GitHub-flavored Markdown. + +### `trace.explain(trace, options)` + +Calls an OpenAI-compatible endpoint and returns a short explanation of why the request was slow. Accepts `{ apiKey, model, baseUrl }`. + +### `trace.buildExplainPrompt(trace)` + +Returns `{ system, user }` prompt text so you can run the explanation in any chat tool without a key. + +### `trace.enableAutoInstrumentation(options)` + +Patches supported drivers (`pg`, `mongodb`, `ioredis`) and returns the list that was applied. Accepts `{ only: [...] }`. + +### `trace.disableAutoInstrumentation()` + +Restores the original driver methods. + +### `trace.instrumentKnex(knexInstance)` + +Attaches query timing to a `knex` instance via its event hooks. + +### `trace.instrumentPrisma(prismaClient)` + +Adds query timing through Prisma's `$use` middleware. + ### `trace.useLogger(type, logger)` Supports `"console"`, `"pino"`, `"winston"`, or a custom `{ onTrace(trace) {} }` integration. @@ -397,13 +563,21 @@ Patches outgoing `http`, `https`, and `fetch` calls. Restores the original outgoing HTTP functions. -### `trace.exportChromeTrace(trace)` +### `trace.exportChromeTrace(trace)` / `trace.exportChromeTraceJson(trace)` -Returns Chrome Trace Event Format data. +Returns Chrome Trace Event Format data, as an object or a JSON string. -### `trace.exportChromeTraceJson(trace)` +### `trace.exportSpeedscope(trace)` / `trace.exportSpeedscopeJson(trace)` -Returns Chrome Trace Event Format as a JSON string. +Returns a Speedscope profile, as an object or a JSON string. + +### `trace.toMarkdown(trace, options)` + +Returns a GitHub-flavored Markdown report for a trace. + +### `trace.toShareableHtml(trace)` + +Returns a self-contained HTML document for the trace. ### `trace.sanitizeHeaders(headers)` @@ -411,7 +585,7 @@ Redacts sensitive headers using the configured list. ### `trace.destroy()` -Stops cleanup timers, clears stored traces, disables HTTP tracing, and resets the tracer. +Stops cleanup timers, clears stored traces, disables HTTP tracing and auto-instrumentation, and resets the tracer. ## Configuration @@ -422,6 +596,7 @@ Stops cleanup timers, clears stored traces, disables HTTP tracing, and resets th | `maxTraces` | `1000` | Maximum number of traces stored in memory | | `retentionSeconds` | `300` | How long traces stay in memory | | `autoTrack` | `false` | Enables framework middleware/lifecycle timing | +| `autoInstrument` | `false` | Enables driver instrumentation; pass `{ only: [...] }` to limit it | | `traceOutgoing` | `false` | Enables outgoing HTTP and fetch tracing | | `sensitiveHeaders` | `null` | Custom sensitive header list | @@ -433,6 +608,7 @@ In development, run with full sampling and rich instrumentation: trace.init({ samplingRate: 1, autoTrack: true, + autoInstrument: true, traceOutgoing: true, }); ``` @@ -456,6 +632,7 @@ This library stores traces in memory. It is intentionally lightweight and local- - Request and response bodies are not captured. - Sensitive headers are redacted. +- Auto-instrumented query labels are truncated and strip literal values. - The default redaction list includes `Authorization`, `Cookie`, `Set-Cookie`, `X-API-Key`, `X-Auth-Token`, and `Proxy-Authorization`. Customize header redaction: @@ -466,6 +643,8 @@ trace.init({ }); ``` +AI explanations are opt-in and only send the trace summary you generate. No key is bundled, and requests go directly to the endpoint you configure. + ## Performance The library is designed to stay small: diff --git a/assets/node-request-trace-readme-hero.png b/assets/node-request-trace-readme-hero.png new file mode 100644 index 0000000..cd494e6 Binary files /dev/null and b/assets/node-request-trace-readme-hero.png differ diff --git a/bin/cli.js b/bin/cli.js index 56a018b..2c48c55 100644 --- a/bin/cli.js +++ b/bin/cli.js @@ -31,7 +31,12 @@ ${BOLD}Commands:${RESET} ${GREEN}inspect${RESET} Show single trace detail ${GREEN}timeline${RESET} Show request timeline report ${GREEN}tail${RESET} Live tail of incoming traces + ${GREEN}diff${RESET} Compare two traces (regression diff) + ${GREEN}markdown${RESET} Print GitHub-flavored markdown (alias: md) + ${GREEN}snapshot${RESET} Save a self-contained shareable .html file + ${GREEN}explain${RESET} AI explanation of why a request was slow ${GREEN}export${RESET} Export trace as Chrome Trace JSON + ${GREEN}speedscope${RESET} Export trace as Speedscope JSON ${BOLD}Examples:${RESET} npx node-request-trace stats http://localhost:3000 @@ -39,7 +44,12 @@ ${BOLD}Examples:${RESET} npx node-request-trace inspect http://localhost:3000 req_abc123 npx node-request-trace timeline http://localhost:3000 req_abc123 npx node-request-trace tail http://localhost:3000 + npx node-request-trace diff http://localhost:3000 req_aaa req_bbb + npx node-request-trace markdown http://localhost:3000 req_abc123 + npx node-request-trace snapshot http://localhost:3000 req_abc123 > trace.html + npx node-request-trace explain http://localhost:3000 req_abc123 npx node-request-trace export http://localhost:3000 req_abc123 > trace.json + npx node-request-trace speedscope http://localhost:3000 req_abc > scope.json `; function fetchJson(url) { @@ -59,6 +69,22 @@ function fetchJson(url) { }); } +function fetchText(url) { + return new Promise((resolve, reject) => { + const mod = url.startsWith('https') ? https : http; + mod.get(url, (res) => { + let data = ''; + res.on('data', (chunk) => { data += chunk; }); + res.on('end', () => { + if (res.statusCode >= 400) { + return reject(new Error(`HTTP ${res.statusCode}: ${data}`)); + } + resolve(data); + }); + }).on('error', reject); + }); +} + function methodColor(m) { switch (m) { case 'GET': return GREEN; @@ -268,6 +294,104 @@ async function cmdExport(baseUrl, requestId) { console.log(JSON.stringify(chromeTrace, null, 2)); } +async function cmdSpeedscope(baseUrl, requestId) { + if (!requestId) { + console.error(`${RED}Error: request ID required${RESET}`); + console.error('Usage: npx node-request-trace speedscope '); + process.exit(1); + } + const profile = await fetchJson(`${baseUrl}/trace/${requestId}/speedscope`); + console.log(JSON.stringify(profile, null, 2)); +} + +async function cmdMarkdown(baseUrl, requestId) { + if (!requestId) { + console.error(`${RED}Error: request ID required${RESET}`); + console.error('Usage: npx node-request-trace markdown '); + process.exit(1); + } + const md = await fetchText(`${baseUrl}/trace/${requestId}/markdown`); + console.log(md); +} + +async function cmdSnapshot(baseUrl, requestId) { + if (!requestId) { + console.error(`${RED}Error: request ID required${RESET}`); + console.error('Usage: npx node-request-trace snapshot > trace.html'); + process.exit(1); + } + const html = await fetchText(`${baseUrl}/trace/${requestId}/snapshot`); + // If stdout is a TTY, write a file; otherwise stream for redirection. + if (process.stdout.isTTY) { + const fs = require('node:fs'); + const file = `${requestId}.html`; + fs.writeFileSync(file, html); + console.log(`\n ${GREEN}Saved${RESET} ${file} ${DIM}(open in a browser, or share the file)${RESET}\n`); + } else { + process.stdout.write(html); + } +} + +async function cmdDiff(baseUrl, idA, idB) { + if (!idA || !idB) { + console.error(`${RED}Error: two request IDs required${RESET}`); + console.error('Usage: npx node-request-trace diff '); + process.exit(1); + } + const diff = await fetchJson(`${baseUrl}/trace/diff/${idA}/${idB}`); + printDiff(diff); +} + +async function cmdExplain(baseUrl, requestId) { + if (!requestId) { + console.error(`${RED}Error: request ID required${RESET}`); + console.error('Usage: npx node-request-trace explain '); + process.exit(1); + } + const { buildExplainPrompt, explainTrace } = require('../lib/explain'); + const trace = await fetchJson(`${baseUrl}/trace/${requestId}`); + + if (!process.env.OPENAI_API_KEY && !process.env.LLM_API_KEY) { + const { system, user } = buildExplainPrompt(trace); + console.log(`\n${YELLOW}No API key set (OPENAI_API_KEY / LLM_API_KEY).${RESET}`); + console.log(`${DIM}Copy the prompt below into your LLM of choice:${RESET}\n`); + console.log(`${DIM}--- system ---${RESET}\n${system}\n`); + console.log(`${DIM}--- user ---${RESET}\n${user}\n`); + return; + } + + console.log(`\n${DIM} Asking the model...${RESET}\n`); + const answer = await explainTrace(trace); + console.log(answer + '\n'); +} + +function printDiff(diff) { + const arrow = diff.totalDeltaMs > 0 ? `${RED}๐Ÿ”บ${RESET}` : diff.totalDeltaMs < 0 ? `${GREEN}๐Ÿ”ป${RESET}` : 'โž–'; + console.log(`\n${BOLD} Trace diff: ${diff.b.method} ${diff.b.path}${RESET}\n`); + const pct = diff.totalDeltaPercent === null ? 'n/a' : `${diff.totalDeltaPercent}%`; + const sign = diff.totalDeltaMs > 0 ? '+' : ''; + console.log( + ` ${arrow} Total: ${diff.a.totalDuration}ms โ†’ ${diff.b.totalDuration}ms ` + + `(${sign}${diff.totalDeltaMs}ms, ${pct})` + + (diff.regressed ? ` ${RED}โš  regression${RESET}` : '') + ); + console.log(); + for (const s of diff.steps) { + if (s.status === 'unchanged') continue; + let label; + if (s.status === 'added') label = `${BLUE}added${RESET}`; + else if (s.status === 'removed') label = `${GRAY}removed${RESET}`; + else if (s.status === 'slower') label = `${RED}slower${RESET}`; + else label = `${GREEN}faster${RESET}`; + const sgn = s.deltaMs > 0 ? '+' : ''; + console.log( + ` ${padRight(s.name, 28)} ${padLeft(s.durationA + 'ms', 8)} โ†’ ` + + `${padLeft(s.durationB + 'ms', 8)} ${padLeft(sgn + s.deltaMs + 'ms', 9)} ${label}` + ); + } + console.log(); +} + async function main() { const args = process.argv.slice(2); const command = args[0]; @@ -294,7 +418,13 @@ async function main() { case 'inspect': return await cmdInspect(cleanUrl, args[2]); case 'timeline': return await cmdTimeline(cleanUrl, args[2]); case 'tail': return await cmdTail(cleanUrl); + case 'diff': return await cmdDiff(cleanUrl, args[2], args[3]); + case 'markdown': + case 'md': return await cmdMarkdown(cleanUrl, args[2]); + case 'snapshot': return await cmdSnapshot(cleanUrl, args[2]); + case 'explain': return await cmdExplain(cleanUrl, args[2]); case 'export': return await cmdExport(cleanUrl, args[2]); + case 'speedscope': return await cmdSpeedscope(cleanUrl, args[2]); default: console.error(`${RED}Unknown command: ${command}${RESET}`); console.log(USAGE); diff --git a/index.d.ts b/index.d.ts index 6d6efe9..0d049fe 100644 --- a/index.d.ts +++ b/index.d.ts @@ -36,6 +36,7 @@ declare namespace requestTrace { retentionSeconds?: number; autoTrack?: boolean; traceOutgoing?: boolean; + autoInstrument?: boolean | { only?: string[] }; logBody?: boolean; sensitiveHeaders?: string[] | null; } @@ -45,6 +46,84 @@ declare namespace requestTrace { summary: Record; } + interface RepetitionEntry { + pattern: string; + sample: string; + type: string | null; + count: number; + totalDuration: number; + maxDuration: number; + avgDuration: number; + errorCount: number; + isNPlusOne: boolean; + } + + interface RepetitionAnalysis { + duplicates: RepetitionEntry[]; + nPlusOne: RepetitionEntry[]; + hasNPlusOne: boolean; + duplicateCount: number; + wastedDuration: number; + } + + interface DiffStep { + name: string; + status: 'added' | 'removed' | 'slower' | 'faster' | 'unchanged'; + durationA: number; + durationB: number; + deltaMs: number; + deltaPercent: number | null; + countA: number; + countB: number; + } + + interface TraceDiff { + a: Record; + b: Record; + totalDeltaMs: number; + totalDeltaPercent: number | null; + regressed: boolean; + added: DiffStep[]; + removed: DiffStep[]; + slower: DiffStep[]; + faster: DiffStep[]; + steps: DiffStep[]; + } + + interface DiffOptions { + regressionPercent?: number; + } + + interface ExplainPrompt { + system: string; + user: string; + report: TimelineReport; + } + + interface ExplainOptions { + apiKey?: string; + baseUrl?: string; + model?: string; + temperature?: number; + } + + interface MarkdownOptions { + slowThreshold?: number; + } + + interface SpeedscopeProfile { + $schema: string; + name: string; + activeProfileIndex: number; + exporter: string; + shared: { frames: Array<{ name: string }> }; + profiles: unknown[]; + } + + interface AutoInstrumentOptions { + only?: string[]; + } + interface LoggerIntegration { onTrace(trace: Trace): void; } @@ -67,6 +146,19 @@ declare namespace requestTrace { isHttpTracingEnabled(): boolean; exportChromeTrace(trace: Trace): unknown[]; exportChromeTraceJson(trace: Trace): string; + exportSpeedscope(trace?: Trace | null): SpeedscopeProfile; + exportSpeedscopeJson(trace?: Trace | null): string; + toShareableHtml(trace?: Trace | null): string; + toMarkdown(trace?: Trace | null, options?: MarkdownOptions): string; + diff(traceA: Trace, traceB: Trace, options?: DiffOptions): TraceDiff; + diffToMarkdown(traceA: Trace, traceB: Trace, options?: DiffOptions): string; + analyze(trace?: Trace | null): RepetitionAnalysis; + buildExplainPrompt(trace?: Trace | null): ExplainPrompt; + explain(trace?: Trace | null, options?: ExplainOptions): Promise; + enableAutoInstrumentation(options?: AutoInstrumentOptions): string[]; + disableAutoInstrumentation(): this; + instrumentKnex(knexInstance: any): any; + instrumentPrisma(prismaClient: any): any; timeline(trace?: Trace | null): TimelineReport; renderTimeline(trace?: Trace | null, options?: { width?: number }): string; sanitizeHeaders(headers: Record): Record; diff --git a/index.js b/index.js index 16714b7..a772590 100644 --- a/index.js +++ b/index.js @@ -11,6 +11,18 @@ const { createPinoIntegration, createWinstonIntegration, createConsoleIntegratio const { sanitizeHeaders } = require('./lib/security'); const { enableHttpTracing, disableHttpTracing, isEnabled: isHttpTracingEnabled } = require('./lib/http-tracer'); const { toChromeTraceFormat, toChromeTraceJson } = require('./lib/chrome-trace'); +const { toSpeedscope, toSpeedscopeJson } = require('./lib/speedscope'); +const { toShareableHtml } = require('./lib/snapshot'); +const { toMarkdown } = require('./lib/markdown'); +const { diffTraces, diffToMarkdown } = require('./lib/diff'); +const { buildExplainPrompt, explainTrace } = require('./lib/explain'); +const { analyzeRepetition } = require('./lib/analysis'); +const { + enableAutoInstrumentation, + disableAutoInstrumentation, + instrumentKnexInstance, + instrumentPrismaClient, +} = require('./lib/auto-instrument'); const { buildTimeline, renderTimeline: renderTimelineReport } = require('./lib/timeline'); const DEFAULT_CONFIG = { @@ -20,6 +32,7 @@ const DEFAULT_CONFIG = { retentionSeconds: 300, autoTrack: false, traceOutgoing: false, + autoInstrument: false, logBody: false, sensitiveHeaders: null, }; @@ -45,6 +58,12 @@ class RequestTracer { enableHttpTracing(); } + if (this.config.autoInstrument) { + this._autoInstrumented = enableAutoInstrumentation( + typeof this.config.autoInstrument === 'object' ? this.config.autoInstrument : {} + ); + } + return this; } @@ -137,6 +156,62 @@ class RequestTracer { return toChromeTraceJson(trace); } + exportSpeedscope(trace = this.current()) { + return toSpeedscope(trace); + } + + exportSpeedscopeJson(trace = this.current()) { + return toSpeedscopeJson(trace); + } + + toShareableHtml(trace = this.current()) { + return toShareableHtml(trace); + } + + toMarkdown(trace = this.current(), options) { + return toMarkdown(trace, { slowThreshold: this.config.slowThreshold, ...options }); + } + + diff(traceA, traceB, options) { + return diffTraces(traceA, traceB, options); + } + + diffToMarkdown(traceA, traceB, options) { + return diffToMarkdown(diffTraces(traceA, traceB, options)); + } + + analyze(trace = this.current()) { + const t = trace || {}; + return analyzeRepetition(t.steps); + } + + buildExplainPrompt(trace = this.current()) { + return buildExplainPrompt(trace); + } + + explain(trace = this.current(), options) { + return explainTrace(trace, options); + } + + enableAutoInstrumentation(options) { + this._autoInstrumented = enableAutoInstrumentation(options); + return this._autoInstrumented; + } + + disableAutoInstrumentation() { + disableAutoInstrumentation(); + this._autoInstrumented = []; + return this; + } + + instrumentKnex(knexInstance) { + return instrumentKnexInstance(knexInstance); + } + + instrumentPrisma(prismaClient) { + return instrumentPrismaClient(prismaClient); + } + timeline(trace = this.current()) { return buildTimeline(trace); } @@ -155,6 +230,8 @@ class RequestTracer { this.storage.clear(); } disableHttpTracing(); + disableAutoInstrumentation(); + this._autoInstrumented = []; this._initialized = false; } diff --git a/lib/analysis.js b/lib/analysis.js new file mode 100644 index 0000000..6ed7d86 --- /dev/null +++ b/lib/analysis.js @@ -0,0 +1,122 @@ +'use strict'; + +// Detects repeated work within a single request (N+1 queries, duplicate +// service calls, hot loops). Operates on the flat step list so it works +// with the existing trace shape and outgoing-HTTP steps. + +const DEFAULT_DUPLICATE_THRESHOLD = 3; // >=N identical steps is suspicious +const DEFAULT_N_PLUS_ONE_THRESHOLD = 5; // >=N identical steps reads as N+1 + +// Collapses dynamic parts of a step name so semantically identical work +// groups together: numbers, hex ids, UUIDs, quoted literals. +function normalizeStepName(name) { + if (typeof name !== 'string') return String(name); + let out = name; + // Strip query string from outgoing-HTTP step urls. + out = out.replace(/\?.*$/, ''); + // UUIDs. + out = out.replace(/[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}/gi, ''); + // Long hex blobs (mongo ids, request ids, hashes). + out = out.replace(/\b[0-9a-f]{16,}\b/gi, ''); + // Quoted string literals (SQL). + out = out.replace(/'[^']*'/g, "'?'").replace(/"[^"]*"/g, '"?"'); + // IN (...) lists. + out = out.replace(/\bIN\s*\([^)]*\)/gi, 'IN (?)'); + // Standalone numbers (ids, offsets) -> ?. + out = out.replace(/\b\d+\b/g, '?'); + // Collapse whitespace. + out = out.replace(/\s+/g, ' ').trim(); + return out; +} + +function groupSteps(steps) { + const groups = new Map(); + if (!Array.isArray(steps)) return groups; + + for (const step of steps) { + if (!step || !step.name) continue; + const key = normalizeStepName(step.name); + let group = groups.get(key); + if (!group) { + group = { + pattern: key, + sample: step.name, + type: step.type || null, + count: 0, + totalDuration: 0, + maxDuration: 0, + errorCount: 0, + }; + groups.set(key, group); + } + group.count += 1; + const duration = Number(step.duration) || 0; + group.totalDuration += duration; + if (duration > group.maxDuration) group.maxDuration = duration; + if (step.error) group.errorCount += 1; + } + + return groups; +} + +function analyzeRepetition(steps, options = {}) { + const duplicateThreshold = options.duplicateThreshold || DEFAULT_DUPLICATE_THRESHOLD; + const nPlusOneThreshold = options.nPlusOneThreshold || DEFAULT_N_PLUS_ONE_THRESHOLD; + const groups = groupSteps(steps); + + const duplicates = []; + for (const group of groups.values()) { + if (group.count >= duplicateThreshold) { + duplicates.push({ + pattern: group.pattern, + sample: group.sample, + type: group.type, + count: group.count, + totalDuration: group.totalDuration, + maxDuration: group.maxDuration, + avgDuration: Number((group.totalDuration / group.count).toFixed(1)), + errorCount: group.errorCount, + isNPlusOne: group.count >= nPlusOneThreshold, + }); + } + } + + // Worst offenders first: N+1 before plain duplicates, then by total time. + duplicates.sort((a, b) => { + if (a.isNPlusOne !== b.isNPlusOne) return a.isNPlusOne ? -1 : 1; + return b.totalDuration - a.totalDuration; + }); + + const nPlusOne = duplicates.filter(d => d.isNPlusOne); + + return { + duplicates, + nPlusOne, + hasNPlusOne: nPlusOne.length > 0, + duplicateCount: duplicates.length, + wastedDuration: duplicates.reduce( + (sum, d) => sum + (d.totalDuration - d.maxDuration), + 0 + ), + }; +} + +// Human-readable warning lines, e.g. +// "โš ๏ธ N+1 detected: db.user.find ran 23ร— (180ms total)" +function formatRepetitionWarnings(analysis, options = {}) { + if (!analysis || !analysis.duplicates.length) return []; + const icon = options.ascii ? '[!]' : 'โš ๏ธ'; + return analysis.duplicates.map(d => { + const label = d.isNPlusOne ? 'N+1 detected' : 'Duplicate work'; + return `${icon} ${label}: ${d.sample} ran ${d.count}ร— (${d.totalDuration}ms total)`; + }); +} + +module.exports = { + normalizeStepName, + groupSteps, + analyzeRepetition, + formatRepetitionWarnings, + DEFAULT_DUPLICATE_THRESHOLD, + DEFAULT_N_PLUS_ONE_THRESHOLD, +}; diff --git a/lib/auto-instrument.js b/lib/auto-instrument.js new file mode 100644 index 0000000..6edf9dd --- /dev/null +++ b/lib/auto-instrument.js @@ -0,0 +1,266 @@ +'use strict'; + +const { currentTrace } = require('./trace-engine'); + +// Auto-instrumentation for popular data libraries. Each integration is opt-in +// and best-effort: if the module isn't installed or the internals differ, we +// skip silently rather than crash the host app. Steps are pushed onto the +// active trace via AsyncLocalStorage, so no manual trace.step() is needed. + +const _patched = new Set(); +const _restore = []; + +function recordStep(name, type, start, error) { + const trace = currentTrace(); + if (!trace) return; + const step = { name, start, duration: Date.now() - start, type }; + if (error) step.error = error.message || String(error); + trace.steps.push(step); +} + +function tryRequire(name) { + if (_requireOverride) return _requireOverride(name); + try { + return require(name); + } catch (_) { + return null; + } +} + +// Test seam: lets the suite inject fake drivers so the patch paths are +// exercised without installing pg/mongodb/ioredis. Not part of the public API. +let _requireOverride = null; +function __setRequireForTests(fn) { + _requireOverride = fn; +} + +// Wrap a function that returns a promise, timing it as a step. +function timePromise(name, type, fn, thisArg, args) { + const start = Date.now(); + let result; + try { + result = fn.apply(thisArg, args); + } catch (err) { + recordStep(name, type, start, err); + throw err; + } + if (result && typeof result.then === 'function') { + return result.then( + (value) => { recordStep(name, type, start); return value; }, + (err) => { recordStep(name, type, start, err); throw err; } + ); + } + recordStep(name, type, start); + return result; +} + +// --- pg (node-postgres) --------------------------------------------------- +function instrumentPg() { + const pg = tryRequire('pg'); + if (!pg || !pg.Client || _patched.has('pg')) return false; + const proto = pg.Client.prototype; + const orig = proto.query; + if (typeof orig !== 'function') return false; + + proto.query = function tracedQuery(...args) { + const sql = typeof args[0] === 'string' ? args[0] : (args[0] && args[0].text) || 'query'; + const name = `pg ${truncateSql(sql)}`; + // pg.query supports both callback and promise styles; only time promise. + const last = args[args.length - 1]; + if (typeof last === 'function') { + const start = Date.now(); + const cb = args[args.length - 1]; + args[args.length - 1] = function (err, ...rest) { + recordStep(name, 'db', start, err); + return cb(err, ...rest); + }; + return orig.apply(this, args); + } + return timePromise(name, 'db', orig, this, args); + }; + + _patched.add('pg'); + _restore.push(() => { proto.query = orig; _patched.delete('pg'); }); + return true; +} + +// --- mysql2 --------------------------------------------------------------- +function instrumentMysql2() { + const mysql = tryRequire('mysql2'); + if (!mysql || _patched.has('mysql2')) return false; + const promiseMod = tryRequire('mysql2/promise'); + let patchedAny = false; + + if (promiseMod && promiseMod.Connection) { + // Newer mysql2 exposes prototypes lazily; patch via createConnection wrap. + } + + // Patch the core Connection.prototype.query if reachable. + const core = tryRequire('mysql2'); + const Connection = core && core.Connection; + if (Connection && Connection.prototype && typeof Connection.prototype.query === 'function') { + const orig = Connection.prototype.query; + Connection.prototype.query = function tracedQuery(sql, ...rest) { + const text = typeof sql === 'string' ? sql : (sql && sql.sql) || 'query'; + const name = `mysql ${truncateSql(text)}`; + const start = Date.now(); + const last = rest[rest.length - 1]; + if (typeof last === 'function') { + rest[rest.length - 1] = function (err, ...r) { + recordStep(name, 'db', start, err); + return last(err, ...r); + }; + return orig.call(this, sql, ...rest); + } + const out = orig.call(this, sql, ...rest); + if (out && typeof out.then === 'function') { + return out.then( + (v) => { recordStep(name, 'db', start); return v; }, + (e) => { recordStep(name, 'db', start, e); throw e; } + ); + } + recordStep(name, 'db', start); + return out; + }; + _restore.push(() => { Connection.prototype.query = orig; }); + patchedAny = true; + } + + if (patchedAny) _patched.add('mysql2'); + return patchedAny; +} + +// --- mongodb -------------------------------------------------------------- +function instrumentMongodb() { + const mongo = tryRequire('mongodb'); + if (!mongo || !mongo.Collection || _patched.has('mongodb')) return false; + const proto = mongo.Collection.prototype; + const methods = ['find', 'findOne', 'insertOne', 'insertMany', 'updateOne', + 'updateMany', 'deleteOne', 'deleteMany', 'aggregate', 'countDocuments']; + let patchedAny = false; + + for (const method of methods) { + const orig = proto[method]; + if (typeof orig !== 'function') continue; + proto[method] = function tracedMongo(...args) { + const name = `mongo ${this.collectionName || 'collection'}.${method}`; + // find/aggregate return cursors (lazy); time the sync call only. + if (method === 'find' || method === 'aggregate') { + const start = Date.now(); + const cursor = orig.apply(this, args); + recordStep(name, 'db', start); + return cursor; + } + return timePromise(name, 'db', orig, this, args); + }; + _restore.push(() => { proto[method] = orig; }); + patchedAny = true; + } + + if (patchedAny) _patched.add('mongodb'); + return patchedAny; +} + +// --- redis / ioredis ------------------------------------------------------ +function instrumentRedis() { + let patchedAny = false; + + // ioredis: patch sendCommand. + const IORedis = tryRequire('ioredis'); + if (IORedis && !_patched.has('ioredis')) { + const proto = IORedis.prototype || (IORedis.default && IORedis.default.prototype); + if (proto && typeof proto.sendCommand === 'function') { + const orig = proto.sendCommand; + proto.sendCommand = function tracedSend(command, ...rest) { + const cmdName = command && command.name ? command.name : 'cmd'; + const name = `redis ${String(cmdName).toUpperCase()}`; + return timePromise(name, 'cache', orig, this, [command, ...rest]); + }; + _patched.add('ioredis'); + _restore.push(() => { proto.sendCommand = orig; _patched.delete('ioredis'); }); + patchedAny = true; + } + } + + return patchedAny; +} + +// --- knex ----------------------------------------------------------------- +function instrumentKnex() { + const knex = tryRequire('knex'); + if (!knex || _patched.has('knex')) return false; + // knex emits 'query'/'query-response' events per instance; we can't patch a + // prototype reliably across versions. Expose a helper instead. + _patched.add('knex'); + return true; +} + +// Attach to a knex instance's event hooks (call manually since knex is +// instance-based): instrumentKnexInstance(knexInstance). +function instrumentKnexInstance(knexInstance) { + if (!knexInstance || typeof knexInstance.on !== 'function') return knexInstance; + const starts = new Map(); + knexInstance.on('query', (q) => { starts.set(q.__knexQueryUid, Date.now()); }); + const finish = (q, err) => { + const start = starts.get(q.__knexQueryUid) || Date.now(); + starts.delete(q.__knexQueryUid); + recordStep(`knex ${truncateSql(q.sql || 'query')}`, 'db', start, err); + }; + knexInstance.on('query-response', (_resp, q) => finish(q)); + knexInstance.on('query-error', (err, q) => finish(q, err)); + return knexInstance; +} + +// --- prisma --------------------------------------------------------------- +// Prisma is best instrumented via its $use middleware on a client instance. +function instrumentPrismaClient(prismaClient) { + if (!prismaClient || typeof prismaClient.$use !== 'function') return prismaClient; + prismaClient.$use(async (params, next) => { + const name = `prisma ${params.model || ''}.${params.action}`.trim(); + const start = Date.now(); + try { + const result = await next(params); + recordStep(name, 'db', start); + return result; + } catch (err) { + recordStep(name, 'db', start, err); + throw err; + } + }); + return prismaClient; +} + +function truncateSql(sql) { + const s = String(sql).replace(/\s+/g, ' ').trim(); + return s.length > 60 ? s.slice(0, 57) + '...' : s; +} + +// Enable all auto-detectable integrations. Returns the list that were applied. +function enableAutoInstrumentation(options = {}) { + const only = options.only; // optional array of names + const want = (name) => !only || only.includes(name); + const applied = []; + if (want('pg') && instrumentPg()) applied.push('pg'); + if (want('mysql2') && instrumentMysql2()) applied.push('mysql2'); + if (want('mongodb') && instrumentMongodb()) applied.push('mongodb'); + if (want('redis') && instrumentRedis()) applied.push('redis'); + if (want('knex') && instrumentKnex()) applied.push('knex'); + return applied; +} + +function disableAutoInstrumentation() { + while (_restore.length) { + const restore = _restore.pop(); + try { restore(); } catch (_) { /* ignore */ } + } + _patched.clear(); +} + +module.exports = { + enableAutoInstrumentation, + disableAutoInstrumentation, + instrumentKnexInstance, + instrumentPrismaClient, + __setRequireForTests, + _patched, +}; diff --git a/lib/dashboard.js b/lib/dashboard.js index b41cf0f..c53249b 100644 --- a/lib/dashboard.js +++ b/lib/dashboard.js @@ -245,6 +245,25 @@ async function exportChrome(id) { URL.revokeObjectURL(a.href); } +async function exportDownload(id, suffix, ext, mime) { + const r = await fetch('/trace/' + id + '/' + suffix); + if (!r.ok) return; + const data = await r.text(); + const blob = new Blob([data], { type: mime }); + const a = document.createElement('a'); + a.href = URL.createObjectURL(blob); + a.download = 'trace-' + id + '.' + ext; + a.click(); + URL.revokeObjectURL(a.href); +} + +async function copyMarkdown(id) { + const r = await fetch('/trace/' + id + '/markdown'); + if (!r.ok) return; + const md = await r.text(); + try { await navigator.clipboard.writeText(md); } catch (_) {} +} + async function showDetail(id) { const r = await fetch('/trace/' + id); if (!r.ok) return; @@ -255,6 +274,9 @@ async function showDetail(id) { p.innerHTML = '' + '

' + t.method + ' ' + t.path + '' + + '' + + '' + + '' + '

' + '
' + '
Request ID
' + t.requestId + '
' diff --git a/lib/diff.js b/lib/diff.js new file mode 100644 index 0000000..2faad0a --- /dev/null +++ b/lib/diff.js @@ -0,0 +1,129 @@ +'use strict'; + +const { buildTimeline } = require('./timeline'); +const { groupSteps } = require('./analysis'); + +// Compares two traces (a baseline "A" and a candidate "B") and reports how the +// request shape changed: total duration delta, per-step regressions, added and +// removed steps. Built for PR comments and CI gates. +function diffTraces(traceA, traceB, options = {}) { + const a = buildTimeline(traceA); + const b = buildTimeline(traceB); + + const groupsA = aggregateGroups(a.steps); + const groupsB = aggregateGroups(b.steps); + const keys = new Set([...groupsA.keys(), ...groupsB.keys()]); + + const steps = []; + for (const key of keys) { + const ga = groupsA.get(key); + const gb = groupsB.get(key); + const durA = ga ? ga.totalDuration : 0; + const durB = gb ? gb.totalDuration : 0; + let status; + if (!ga) status = 'added'; + else if (!gb) status = 'removed'; + else if (durB > durA) status = 'slower'; + else if (durB < durA) status = 'faster'; + else status = 'unchanged'; + + steps.push({ + name: (gb || ga).sample, + status, + durationA: durA, + durationB: durB, + deltaMs: durB - durA, + deltaPercent: percentChange(durA, durB), + countA: ga ? ga.count : 0, + countB: gb ? gb.count : 0, + }); + } + + // Most impactful changes first (largest absolute time delta). + steps.sort((x, y) => Math.abs(y.deltaMs) - Math.abs(x.deltaMs)); + + const totalDelta = b.totalDuration - a.totalDuration; + const regressionThreshold = options.regressionPercent || 0; + const totalPercent = percentChange(a.totalDuration, b.totalDuration); + const regressed = + totalPercent !== null && totalPercent > regressionThreshold && totalDelta > 0; + + return { + a: summarize(a), + b: summarize(b), + totalDeltaMs: totalDelta, + totalDeltaPercent: totalPercent, + regressed, + added: steps.filter(s => s.status === 'added'), + removed: steps.filter(s => s.status === 'removed'), + slower: steps.filter(s => s.status === 'slower'), + faster: steps.filter(s => s.status === 'faster'), + steps, + }; +} + +function aggregateGroups(steps) { + // Reuse the normalization from analysis so dynamic ids collapse together. + return groupSteps(steps); +} + +function summarize(report) { + return { + requestId: report.requestId, + method: report.method, + path: report.path, + totalDuration: report.totalDuration, + status: report.status, + }; +} + +function percentChange(from, to) { + if (!from) return to ? null : 0; + return Number((((to - from) / from) * 100).toFixed(1)); +} + +// Render a markdown table suitable for a PR comment. +function diffToMarkdown(diff) { + const arrow = diff.totalDeltaMs > 0 ? '๐Ÿ”บ' : diff.totalDeltaMs < 0 ? '๐Ÿ”ป' : 'โž–'; + const pct = diff.totalDeltaPercent === null ? 'n/a' : `${diff.totalDeltaPercent}%`; + const lines = []; + lines.push( + `### ${arrow} Trace diff: \`${diff.b.method} ${diff.b.path}\`` + ); + lines.push(''); + lines.push( + `**Total:** ${diff.a.totalDuration}ms โ†’ ${diff.b.totalDuration}ms ` + + `(${signed(diff.totalDeltaMs)}ms, ${pct})` + + (diff.regressed ? ' โ€” โš ๏ธ **regression**' : '') + ); + lines.push(''); + lines.push('| Step | Before | After | ฮ” | Change |'); + lines.push('|---|---:|---:|---:|---|'); + for (const s of diff.steps) { + if (s.status === 'unchanged') continue; + const change = changeLabel(s); + lines.push( + `| \`${escapeCell(s.name)}\` | ${s.durationA}ms | ${s.durationB}ms | ` + + `${signed(s.deltaMs)}ms | ${change} |` + ); + } + return lines.join('\n'); +} + +function changeLabel(s) { + if (s.status === 'added') return '๐Ÿ†• added'; + if (s.status === 'removed') return '๐Ÿ—‘๏ธ removed'; + const pct = s.deltaPercent === null ? '' : ` (${signed(s.deltaPercent)}%)`; + if (s.status === 'slower') return `๐Ÿ”บ slower${pct}`; + return `๐Ÿ”ป faster${pct}`; +} + +function signed(n) { + return n > 0 ? `+${n}` : `${n}`; +} + +function escapeCell(value) { + return String(value).replace(/\|/g, '\\|'); +} + +module.exports = { diffTraces, diffToMarkdown }; diff --git a/lib/explain.js b/lib/explain.js new file mode 100644 index 0000000..9d92556 --- /dev/null +++ b/lib/explain.js @@ -0,0 +1,105 @@ +'use strict'; + +const { buildTimeline } = require('./timeline'); + +// Builds a compact, structured summary of a trace that's ideal as an LLM +// prompt. Kept separate from any network call so it's testable and usable +// offline (e.g. paste into your own chat). +function buildExplainPrompt(trace) { + const report = buildTimeline(trace); + const s = report.summary; + + const facts = []; + facts.push(`Request: ${report.method} ${report.path} (status ${report.status})`); + facts.push(`Total duration: ${report.totalDuration}ms across ${report.stepCount} steps.`); + if (s.bottleneck) { + facts.push( + `Bottleneck: "${s.bottleneck.name}" took ${s.bottleneck.duration}ms ` + + `(${s.bottleneck.percentOfRequest}% of the request).` + ); + } + facts.push( + `Coverage: ${s.coveragePercent}% of the request is explained by recorded steps; ` + + `${s.uninstrumentedDuration}ms is uninstrumented (untraced time).` + ); + if (s.errorCount) facts.push(`${s.errorCount} step(s) errored.`); + + if (s.duplicates && s.duplicates.length) { + for (const d of s.duplicates) { + facts.push( + `${d.isNPlusOne ? 'N+1 pattern' : 'Duplicate work'}: "${d.sample}" ran ` + + `${d.count}ร— for ${d.totalDuration}ms total.` + ); + } + } + + if (s.gaps && s.gaps.length) { + const biggest = s.gaps.slice().sort((a, b) => b.duration - a.duration)[0]; + facts.push(`Largest untraced gap: ${biggest.duration}ms (${biggest.percentOfRequest}%).`); + } + + const steps = report.steps + .map(st => `- ${st.name}: ${st.duration}ms${st.type ? ` [${st.type}]` : ''}${st.error ? ` ERROR: ${st.error}` : ''}`) + .join('\n'); + + const system = + 'You are a senior performance engineer. Given a single web request trace, ' + + 'explain in 3-5 concise bullet points why it was slow and what to optimize ' + + 'first. Be specific and actionable. Prefer indexing, batching (fixing N+1), ' + + 'caching, and parallelization advice when the data supports it.'; + + const user = + `Trace summary:\n${facts.join('\n')}\n\nSteps (in order):\n${steps || '(none)'}`; + + return { system, user, report }; +} + +// Calls an OpenAI-compatible chat completions endpoint. The caller supplies the +// API key/URL/model so we never bundle a vendor or store secrets. Returns the +// assistant text. Uses global fetch (Node 18+); falls back gracefully. +async function explainTrace(trace, options = {}) { + const { system, user } = buildExplainPrompt(trace); + + const apiKey = options.apiKey || process.env.OPENAI_API_KEY || process.env.LLM_API_KEY; + if (!apiKey) { + const err = new Error( + 'No API key provided. Set OPENAI_API_KEY or pass { apiKey }. ' + + 'You can also use buildExplainPrompt(trace) to copy the prompt manually.' + ); + err.code = 'NO_API_KEY'; + throw err; + } + + const baseUrl = options.baseUrl || process.env.LLM_BASE_URL || 'https://api.openai.com/v1'; + const model = options.model || process.env.LLM_MODEL || 'gpt-4o-mini'; + + if (typeof fetch !== 'function') { + throw new Error('global fetch is unavailable; Node 18+ is required for explainTrace'); + } + + const res = await fetch(`${baseUrl.replace(/\/$/, '')}/chat/completions`, { + method: 'POST', + headers: { + 'Content-Type': 'application/json', + Authorization: `Bearer ${apiKey}`, + }, + body: JSON.stringify({ + model, + temperature: options.temperature ?? 0.2, + messages: [ + { role: 'system', content: system }, + { role: 'user', content: user }, + ], + }), + }); + + if (!res.ok) { + const text = await res.text().catch(() => ''); + throw new Error(`LLM request failed: HTTP ${res.status} ${text}`); + } + + const json = await res.json(); + return json.choices?.[0]?.message?.content?.trim() || ''; +} + +module.exports = { buildExplainPrompt, explainTrace }; diff --git a/lib/markdown.js b/lib/markdown.js new file mode 100644 index 0000000..8d5b9a8 --- /dev/null +++ b/lib/markdown.js @@ -0,0 +1,76 @@ +'use strict'; + +const { buildTimeline, renderTimeline } = require('./timeline'); + +// GitHub-flavored markdown export for a single trace. Designed to be pasted +// directly into a PR description, issue, or incident note. Uses a collapsible +//
block so it stays compact in long threads. +function toMarkdown(trace, options = {}) { + const report = buildTimeline(trace); + const s = report.summary; + const slow = options.slowThreshold && report.totalDuration >= options.slowThreshold; + const emoji = slow ? '๐Ÿข' : 'โšก'; + + const lines = []; + const title = + `${emoji} \`${report.method} ${report.path}\` โ€” **${report.totalDuration}ms** ` + + `(${report.status})`; + lines.push(`
`); + lines.push(`${title}`); + lines.push(''); + + // Summary bullets. + if (report.requestId) lines.push(`- **Request:** \`${report.requestId}\``); + if (s.bottleneck) { + lines.push( + `- **Bottleneck:** \`${s.bottleneck.name}\` ${s.bottleneck.duration}ms ` + + `(${s.bottleneck.percentOfRequest}%)` + ); + } + lines.push( + `- **Coverage:** ${s.coveredDuration}ms traced (${s.coveragePercent}%), ` + + `${s.uninstrumentedDuration}ms uninstrumented` + ); + if (s.errorCount) lines.push(`- **Errors:** ${s.errorCount}`); + + // N+1 / duplicate warnings get pulled to the top โ€” that's the shareable bit. + if (s.duplicates && s.duplicates.length) { + lines.push(''); + for (const d of s.duplicates) { + const label = d.isNPlusOne ? 'โš ๏ธ **N+1 detected**' : 'โš ๏ธ **Duplicate work**'; + lines.push(`- ${label}: \`${d.sample}\` ran **${d.count}ร—** (${d.totalDuration}ms total)`); + } + } + + // Step table. + lines.push(''); + lines.push('| Step | Start | Duration | % | Type |'); + lines.push('|---|---:|---:|---:|---|'); + if (report.steps.length) { + for (const step of report.steps) { + const name = step.error ? `${step.name} โŒ` : step.name; + lines.push( + `| ${escapeCell(name)} | ${step.offset}ms | ${step.duration}ms | ` + + `${step.percentOfRequest}% | ${step.type || ''} |` + ); + } + } else { + lines.push('| _no steps recorded_ | | | | |'); + } + + // ASCII timeline in a code block for the visual hook. + lines.push(''); + lines.push('```txt'); + lines.push(renderTimeline(trace, { ascii: true })); + lines.push('```'); + lines.push(''); + lines.push('
'); + + return lines.join('\n'); +} + +function escapeCell(value) { + return String(value).replace(/\|/g, '\\|'); +} + +module.exports = { toMarkdown }; diff --git a/lib/routes.js b/lib/routes.js index 177d2ad..037f82d 100644 --- a/lib/routes.js +++ b/lib/routes.js @@ -2,6 +2,10 @@ const { getDashboardHtml } = require('./dashboard'); const { toChromeTraceFormat } = require('./chrome-trace'); +const { toSpeedscope } = require('./speedscope'); +const { toShareableHtml } = require('./snapshot'); +const { toMarkdown } = require('./markdown'); +const { diffTraces } = require('./diff'); const { buildTimeline, renderTimeline } = require('./timeline'); function createRouter(tracer) { @@ -47,6 +51,52 @@ function createRouter(tracer) { return res.end(JSON.stringify({ error: 'Trace not found' })); } + const speedscopeMatch = url.match(/^\/trace\/([a-zA-Z0-9_]+)\/speedscope$/); + if (speedscopeMatch) { + const trace = tracer.storage.get(speedscopeMatch[1]); + if (trace) { + return serveJson(res, toSpeedscope(trace)); + } + res.writeHead(404, { 'Content-Type': 'application/json' }); + return res.end(JSON.stringify({ error: 'Trace not found' })); + } + + const markdownMatch = url.match(/^\/trace\/([a-zA-Z0-9_]+)\/markdown$/); + if (markdownMatch) { + const trace = tracer.storage.get(markdownMatch[1]); + if (trace) { + res.writeHead(200, { 'Content-Type': 'text/markdown; charset=utf-8' }); + return res.end(toMarkdown(trace, { slowThreshold: tracer.config.slowThreshold })); + } + res.writeHead(404, { 'Content-Type': 'application/json' }); + return res.end(JSON.stringify({ error: 'Trace not found' })); + } + + const snapshotMatch = url.match(/^\/trace\/([a-zA-Z0-9_]+)\/snapshot$/); + if (snapshotMatch) { + const trace = tracer.storage.get(snapshotMatch[1]); + if (trace) { + res.writeHead(200, { + 'Content-Type': 'text/html; charset=utf-8', + 'Content-Disposition': `attachment; filename="${snapshotMatch[1]}.html"`, + }); + return res.end(toShareableHtml(trace)); + } + res.writeHead(404, { 'Content-Type': 'application/json' }); + return res.end(JSON.stringify({ error: 'Trace not found' })); + } + + const diffMatch = url.match(/^\/trace\/diff\/([a-zA-Z0-9_]+)\/([a-zA-Z0-9_]+)$/); + if (diffMatch) { + const a = tracer.storage.get(diffMatch[1]); + const b = tracer.storage.get(diffMatch[2]); + if (a && b) { + return serveJson(res, diffTraces(a, b)); + } + res.writeHead(404, { 'Content-Type': 'application/json' }); + return res.end(JSON.stringify({ error: 'Trace not found' })); + } + const singleMatch = url.match(/^\/trace\/([a-zA-Z0-9_]+)$/); if (singleMatch) { const trace = tracer.storage.get(singleMatch[1]); diff --git a/lib/snapshot.js b/lib/snapshot.js new file mode 100644 index 0000000..7e3b0ef --- /dev/null +++ b/lib/snapshot.js @@ -0,0 +1,95 @@ +'use strict'; + +const { buildTimeline } = require('./timeline'); + +// Produces a single self-contained HTML file (no external assets, no server) +// that renders a shareable view of one trace. "Send your slow trace to a +// teammate as one .html file." +function toShareableHtml(trace) { + const report = buildTimeline(trace); + const data = JSON.stringify(report).replace(/ + + + + +Trace ${escapeHtml(report.requestId || '')} ยท ${escapeHtml(report.method)} ${escapeHtml(report.path)} + + + +
+

+
+
+
+
+
+
+ + +`; +} + +function escapeHtml(value) { + return String(value) + .replace(/&/g, '&') + .replace(//g, '>'); +} + +module.exports = { toShareableHtml }; diff --git a/lib/speedscope.js b/lib/speedscope.js new file mode 100644 index 0000000..6d73102 --- /dev/null +++ b/lib/speedscope.js @@ -0,0 +1,84 @@ +'use strict'; + +// Speedscope is the de-facto interactive flamegraph viewer +// (https://www.speedscope.app). We emit the "evented" profile format, which is +// the most forgiving for sequential/overlapping spans like ours. +// +// Each step becomes an OpenFrame (O) / CloseFrame (C) event pair on a single +// timeline ordered by start time. Drop the JSON at speedscope.app to explore. +function toSpeedscope(trace) { + const steps = Array.isArray(trace.steps) ? trace.steps : []; + const requestStart = Number(trace.startTime) || firstStart(steps); + + const frames = []; + const frameIndex = new Map(); + const getFrame = (name) => { + if (frameIndex.has(name)) return frameIndex.get(name); + const idx = frames.length; + frames.push({ name }); + frameIndex.set(name, idx); + return idx; + }; + + // Build (start, end, frame) tuples relative to request start, in ms. + const spans = steps.map((step) => { + const at = (Number(step.start) || requestStart) - requestStart; + const dur = Math.max(Number(step.duration) || 0, 0); + return { + frame: getFrame(step.error ? `${step.name} (error)` : step.name), + at: Math.max(at, 0), + end: Math.max(at, 0) + dur, + }; + }); + + // Speedscope evented format requires events in non-decreasing time order, + // with closes before opens at the same timestamp handled via a stack-safe + // ordering. We use a simple sweep producing O then C per span โ€” correct for + // a single-thread sequential view. + const events = []; + for (const span of spans.sort((a, b) => a.at - b.at)) { + events.push({ type: 'O', frame: span.frame, at: span.at }); + events.push({ type: 'C', frame: span.frame, at: span.end }); + } + // Re-sort so all events are time-ordered; on ties, closes precede opens. + events.sort((a, b) => { + if (a.at !== b.at) return a.at - b.at; + if (a.type === b.type) return 0; + return a.type === 'C' ? -1 : 1; + }); + + const totalDuration = Math.max( + Number(trace.duration) || 0, + events.length ? events[events.length - 1].at : 0 + ); + + return { + $schema: 'https://www.speedscope.app/file-format-schema.json', + name: `${trace.method || 'REQ'} ${trace.path || '/'} (${trace.requestId || 'trace'})`, + activeProfileIndex: 0, + exporter: 'node-request-trace', + shared: { frames }, + profiles: [ + { + type: 'evented', + name: `${trace.method || 'REQ'} ${trace.path || '/'}`, + unit: 'milliseconds', + startValue: 0, + endValue: totalDuration, + events, + }, + ], + }; +} + +function toSpeedscopeJson(trace) { + return JSON.stringify(toSpeedscope(trace)); +} + +function firstStart(steps) { + if (!steps.length) return Date.now(); + const starts = steps.map(s => Number(s.start)).filter(Number.isFinite); + return starts.length ? Math.min(...starts) : Date.now(); +} + +module.exports = { toSpeedscope, toSpeedscopeJson }; diff --git a/lib/timeline.js b/lib/timeline.js index 6437e02..95aff97 100644 --- a/lib/timeline.js +++ b/lib/timeline.js @@ -1,5 +1,7 @@ 'use strict'; +const { analyzeRepetition, formatRepetitionWarnings } = require('./analysis'); + const DEFAULT_WIDTH = 48; function buildTimeline(trace) { @@ -21,6 +23,8 @@ function buildTimeline(trace) { return current; }, null); + const repetition = analyzeRepetition(steps); + return { requestId: trace.requestId || null, method: trace.method || 'UNKNOWN', @@ -39,6 +43,10 @@ function buildTimeline(trace) { coveragePercent: percent(coveredDuration, totalDuration), errorCount: steps.filter(step => step.error).length, gaps, + nPlusOne: repetition.nPlusOne, + duplicates: repetition.duplicates, + hasNPlusOne: repetition.hasNPlusOne, + wastedDuration: repetition.wastedDuration, }, }; } @@ -67,6 +75,15 @@ function renderTimeline(trace, options = {}) { `coverage: ${report.summary.coveredDuration}ms traced (${report.summary.coveragePercent}%), ` + `${report.summary.uninstrumentedDuration}ms uninstrumented` ); + + const warnings = formatRepetitionWarnings( + { duplicates: report.summary.duplicates }, + { ascii: options.ascii } + ); + for (const warning of warnings) { + lines.push(warning); + } + lines.push(`0ms |${'-'.repeat(width)}| ${report.totalDuration}ms`); if (!report.steps.length) { diff --git a/package.json b/package.json index 0674b7e..2ee2df0 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "node-request-trace", - "version": "2.2.0", + "version": "2.3.0", "description": "Debug Node.js requests as timelines without OpenTelemetry", "main": "index.js", "types": "index.d.ts", diff --git a/test/run.js b/test/run.js index 9656442..99ac7eb 100644 --- a/test/run.js +++ b/test/run.js @@ -2481,5 +2481,706 @@ test('api: destroy disables http tracing', () => { assert(!httpTracer.isEnabled()); }); +// ========================================================================= +// analysis.js โ€” N+1 / duplicate detection +// ========================================================================= +const analysis = require('../lib/analysis'); + +test('analysis: normalizeStepName collapses ids, uuids, literals', () => { + assertEqual( + analysis.normalizeStepName('SELECT * FROM users WHERE id = 42'), + 'SELECT * FROM users WHERE id = ?' + ); + assertEqual( + analysis.normalizeStepName("SELECT * FROM t WHERE name = 'bob'"), + "SELECT * FROM t WHERE name = '?'" + ); + assertEqual( + analysis.normalizeStepName('GET /api/users/123?foo=bar'), + 'GET /api/users/?' + ); + assertEqual( + analysis.normalizeStepName('find 507f1f77bcf86cd799439011'), + 'find ' + ); +}); + +test('analysis: analyzeRepetition flags N+1 above threshold', () => { + const steps = []; + for (let i = 1; i <= 6; i++) { + steps.push({ name: `SELECT * FROM users WHERE id = ${i}`, duration: 10, type: 'db' }); + } + const result = analysis.analyzeRepetition(steps); + assert(result.hasNPlusOne, 'should detect N+1'); + assertEqual(result.duplicates[0].count, 6); + assertEqual(result.duplicates[0].isNPlusOne, true); + assertEqual(result.duplicates[0].totalDuration, 60); +}); + +test('analysis: duplicates under N+1 threshold are not N+1', () => { + const steps = [ + { name: 'cache.get key 1', duration: 2 }, + { name: 'cache.get key 2', duration: 2 }, + { name: 'cache.get key 3', duration: 2 }, + ]; + const result = analysis.analyzeRepetition(steps); + assertEqual(result.duplicateCount, 1); + assertEqual(result.hasNPlusOne, false); +}); + +test('analysis: unique steps produce no duplicates', () => { + const steps = [ + { name: 'auth', duration: 5 }, + { name: 'render', duration: 8 }, + ]; + const result = analysis.analyzeRepetition(steps); + assertEqual(result.duplicateCount, 0); + assertEqual(result.wastedDuration, 0); +}); + +test('analysis: wastedDuration excludes one max-cost run', () => { + const steps = [ + { name: 'q 1', duration: 10 }, + { name: 'q 2', duration: 10 }, + { name: 'q 3', duration: 30 }, + ]; + const result = analysis.analyzeRepetition(steps); + // total 50, minus the single max (30) = 20 wasted + assertEqual(result.wastedDuration, 20); +}); + +test('analysis: formatRepetitionWarnings produces lines', () => { + const steps = []; + for (let i = 0; i < 5; i++) steps.push({ name: `q ${i}`, duration: 4 }); + const result = analysis.analyzeRepetition(steps); + const lines = analysis.formatRepetitionWarnings(result, { ascii: true }); + assertEqual(lines.length, 1); + assert(lines[0].includes('N+1 detected')); + assert(lines[0].includes('ran 5ร—')); +}); + +test('analysis: empty/invalid steps are safe', () => { + assertEqual(analysis.analyzeRepetition().duplicateCount, 0); + assertEqual(analysis.analyzeRepetition(null).duplicateCount, 0); + assertEqual(analysis.analyzeRepetition([]).duplicateCount, 0); +}); + +// ========================================================================= +// speedscope.js โ€” flamegraph export +// ========================================================================= +const speedscope = require('../lib/speedscope'); + +test('speedscope: toSpeedscope produces evented profile', () => { + const trace = { + requestId: 'ss1', method: 'GET', path: '/x', startTime: 100, duration: 50, status: 200, + steps: [ + { name: 'a', start: 100, duration: 10 }, + { name: 'b', start: 110, duration: 20 }, + ], + }; + const out = speedscope.toSpeedscope(trace); + assertEqual(out.profiles[0].type, 'evented'); + assertEqual(out.shared.frames.length, 2); + assertEqual(out.profiles[0].events.length, 4); // 2 open + 2 close + assertEqual(out.profiles[0].unit, 'milliseconds'); +}); + +test('speedscope: events are time-ordered with closes before opens on ties', () => { + const trace = { + startTime: 0, duration: 10, + steps: [ + { name: 'a', start: 0, duration: 5 }, + { name: 'b', start: 5, duration: 5 }, + ], + }; + const events = speedscope.toSpeedscope(trace).profiles[0].events; + for (let i = 1; i < events.length; i++) { + assert(events[i].at >= events[i - 1].at, 'events must be non-decreasing in time'); + } + // At t=5: close of 'a' must come before open of 'b' + const atFive = events.filter(e => e.at === 5); + assertEqual(atFive[0].type, 'C'); + assertEqual(atFive[1].type, 'O'); +}); + +test('speedscope: toSpeedscopeJson returns valid JSON string', () => { + const json = speedscope.toSpeedscopeJson({ startTime: 0, duration: 1, steps: [] }); + const parsed = JSON.parse(json); + assertEqual(parsed.exporter, 'node-request-trace'); +}); + +test('speedscope: error steps get labeled frames', () => { + const out = speedscope.toSpeedscope({ + startTime: 0, duration: 5, + steps: [{ name: 'boom', start: 0, duration: 5, error: 'x' }], + }); + assert(out.shared.frames[0].name.includes('(error)')); +}); + +// ========================================================================= +// markdown.js โ€” GitHub-flavored export +// ========================================================================= +const markdown = require('../lib/markdown'); + +test('markdown: toMarkdown renders collapsible summary and table', () => { + const trace = { + requestId: 'md1', method: 'POST', path: '/pay', startTime: 0, duration: 120, status: 201, + steps: [{ name: 'charge', start: 10, duration: 100, type: 'http' }], + }; + const md = markdown.toMarkdown(trace); + assert(md.includes('
')); + assert(md.includes('
')); + assert(md.includes('`POST /pay`')); + assert(md.includes('| Step | Start | Duration | % | Type |')); + assert(md.includes('charge')); + assert(md.includes('```txt')); +}); + +test('markdown: slow trace gets turtle emoji', () => { + const trace = { method: 'GET', path: '/', startTime: 0, duration: 900, status: 200, steps: [] }; + const md = markdown.toMarkdown(trace, { slowThreshold: 500 }); + assert(md.includes('๐Ÿข')); +}); + +test('markdown: fast trace gets lightning emoji', () => { + const trace = { method: 'GET', path: '/', startTime: 0, duration: 5, status: 200, steps: [] }; + const md = markdown.toMarkdown(trace, { slowThreshold: 500 }); + assert(md.includes('โšก')); +}); + +test('markdown: N+1 surfaces in markdown bullets', () => { + const steps = []; + for (let i = 1; i <= 5; i++) steps.push({ name: `SELECT x WHERE id = ${i}`, start: i, duration: 5, type: 'db' }); + const md = markdown.toMarkdown({ method: 'GET', path: '/n', startTime: 0, duration: 30, status: 200, steps }); + assert(md.includes('N+1 detected')); +}); + +test('markdown: pipe characters in step names are escaped', () => { + const trace = { + method: 'GET', path: '/', startTime: 0, duration: 10, status: 200, + steps: [{ name: 'a | b', start: 0, duration: 5 }], + }; + const md = markdown.toMarkdown(trace); + assert(md.includes('a \\| b')); +}); + +// ========================================================================= +// snapshot.js โ€” self-contained HTML +// ========================================================================= +const snapshot = require('../lib/snapshot'); + +test('snapshot: toShareableHtml is self-contained (no external src/href except repo link)', () => { + const trace = { + requestId: 'snap1', method: 'GET', path: '/u', startTime: 0, duration: 30, status: 200, + steps: [{ name: 'work', start: 0, duration: 30 }], + }; + const html = snapshot.toShareableHtml(trace); + assert(html.startsWith('')); + assert(html.includes('const R =')); + // No external scripts/styles + assert(!/]+src=/.test(html), 'no external scripts'); + assert(!/]+href=/.test(html), 'no external stylesheets'); +}); + +test('snapshot: embeds trace data and escapes closing tags', () => { + const trace = { + method: 'GET', path: '/', startTime: 0, duration: 5, status: 200, + steps: [{ name: 'x', start: 0, duration: 5 }], + }; + const html = snapshot.toShareableHtml(trace); + // The embedded JSON must not contain a raw closing script tag + assert(!html.includes('x'), 'no premature script close in data'); + assert(html.includes('\\u003c/script>') || html.includes('\\u003c'), 'angle brackets escaped in data'); +}); + +// ========================================================================= +// diff.js โ€” regression diff +// ========================================================================= +const diffMod = require('../lib/diff'); + +function mkTrace(dur, steps) { + return { method: 'GET', path: '/d', startTime: 0, duration: dur, status: 200, steps }; +} + +test('diff: detects slower step and regression', () => { + const a = mkTrace(100, [{ name: 'db query', start: 0, duration: 40 }]); + const b = mkTrace(160, [{ name: 'db query', start: 0, duration: 100 }]); + const d = diffMod.diffTraces(a, b, { regressionPercent: 10 }); + assertEqual(d.totalDeltaMs, 60); + assertEqual(d.regressed, true); + assertEqual(d.slower.length, 1); + assertEqual(d.slower[0].deltaMs, 60); +}); + +test('diff: detects added and removed steps', () => { + const a = mkTrace(50, [{ name: 'old step', start: 0, duration: 50 }]); + const b = mkTrace(60, [{ name: 'new step', start: 0, duration: 60 }]); + const d = diffMod.diffTraces(a, b); + assertEqual(d.added.length, 1); + assertEqual(d.removed.length, 1); + assertEqual(d.added[0].name, 'new step'); + assertEqual(d.removed[0].name, 'old step'); +}); + +test('diff: faster step is not a regression', () => { + const a = mkTrace(100, [{ name: 'x', start: 0, duration: 80 }]); + const b = mkTrace(40, [{ name: 'x', start: 0, duration: 20 }]); + const d = diffMod.diffTraces(a, b, { regressionPercent: 5 }); + assertEqual(d.regressed, false); + assertEqual(d.faster.length, 1); +}); + +test('diff: normalized step names group across dynamic ids', () => { + const a = mkTrace(20, [{ name: 'SELECT WHERE id = 1', start: 0, duration: 20 }]); + const b = mkTrace(40, [{ name: 'SELECT WHERE id = 2', start: 0, duration: 40 }]); + const d = diffMod.diffTraces(a, b); + assertEqual(d.steps.length, 1); + assertEqual(d.steps[0].status, 'slower'); +}); + +test('diff: diffToMarkdown renders table and regression flag', () => { + const a = mkTrace(100, [{ name: 'q', start: 0, duration: 40 }]); + const b = mkTrace(200, [{ name: 'q', start: 0, duration: 140 }]); + const md = diffMod.diffToMarkdown(diffMod.diffTraces(a, b, { regressionPercent: 10 })); + assert(md.includes('Trace diff')); + assert(md.includes('regression')); + assert(md.includes('| Step | Before | After |')); +}); + +// ========================================================================= +// explain.js โ€” AI prompt builder +// ========================================================================= +const explain = require('../lib/explain'); + +test('explain: buildExplainPrompt includes facts and steps', () => { + const trace = { + method: 'GET', path: '/slow', startTime: 0, duration: 500, status: 200, + steps: [{ name: 'db', start: 0, duration: 450, type: 'db' }], + }; + const { system, user } = explain.buildExplainPrompt(trace); + assert(system.includes('performance engineer')); + assert(user.includes('GET /slow')); + assert(user.includes('Bottleneck')); + assert(user.includes('db: 450ms')); +}); + +test('explain: prompt surfaces N+1 patterns', () => { + const steps = []; + for (let i = 1; i <= 6; i++) steps.push({ name: `SELECT id = ${i}`, start: i, duration: 5, type: 'db' }); + const { user } = explain.buildExplainPrompt(mkTrace(60, steps)); + assert(user.includes('N+1 pattern')); +}); + +test('explain: explainTrace rejects without API key', async () => { + const saved = { o: process.env.OPENAI_API_KEY, l: process.env.LLM_API_KEY }; + delete process.env.OPENAI_API_KEY; + delete process.env.LLM_API_KEY; + let threw = false; + try { + await explain.explainTrace(mkTrace(10, [])); + } catch (err) { + threw = true; + assertEqual(err.code, 'NO_API_KEY'); + } + if (saved.o) process.env.OPENAI_API_KEY = saved.o; + if (saved.l) process.env.LLM_API_KEY = saved.l; + assert(threw, 'should throw without API key'); +}); + +// ========================================================================= +// auto-instrument.js +// ========================================================================= +const autoInstrument = require('../lib/auto-instrument'); +const { runWithTrace: rwtAI } = require('../lib/trace-engine'); + +test('auto-instrument: enable returns applied list (best-effort)', () => { + const applied = autoInstrument.enableAutoInstrumentation(); + assert(Array.isArray(applied)); + autoInstrument.disableAutoInstrumentation(); +}); + +test('auto-instrument: instrumentKnexInstance wires event hooks', () => { + const { EventEmitter } = require('node:events'); + const fakeKnex = new EventEmitter(); + const returned = autoInstrument.instrumentKnexInstance(fakeKnex); + assertEqual(returned, fakeKnex); + const trace = { steps: [] }; + rwtAI(trace, () => { + const q = { __knexQueryUid: 'u1', sql: 'SELECT 1' }; + fakeKnex.emit('query', q); + fakeKnex.emit('query-response', {}, q); + }); + assertEqual(trace.steps.length, 1); + assert(trace.steps[0].name.includes('knex')); +}); + +test('auto-instrument: instrumentKnexInstance records query errors', () => { + const { EventEmitter } = require('node:events'); + const fakeKnex = new EventEmitter(); + autoInstrument.instrumentKnexInstance(fakeKnex); + const trace = { steps: [] }; + rwtAI(trace, () => { + const q = { __knexQueryUid: 'e1', sql: 'BAD SQL' }; + fakeKnex.emit('query', q); + fakeKnex.emit('query-error', new Error('boom'), q); + }); + assertEqual(trace.steps[0].error, 'boom'); +}); + +test('auto-instrument: instrumentPrismaClient registers $use middleware', async () => { + let registered = null; + const fakeClient = { $use(fn) { registered = fn; } }; + const returned = autoInstrument.instrumentPrismaClient(fakeClient); + assertEqual(returned, fakeClient); + assert(typeof registered === 'function'); + const trace = { steps: [] }; + await rwtAI(trace, async () => { + await registered({ model: 'User', action: 'findMany' }, async () => ['ok']); + }); + assertEqual(trace.steps.length, 1); + assert(trace.steps[0].name.includes('prisma User.findMany')); +}); + +test('auto-instrument: null instances are returned untouched', () => { + assertEqual(autoInstrument.instrumentKnexInstance(null), null); + assertEqual(autoInstrument.instrumentPrismaClient(null), null); +}); + +// ========================================================================= +// public API โ€” new viral features +// ========================================================================= +const { RequestTracer: RTViral } = require('../index'); + +test('api: analyze detects N+1 on a trace', () => { + const t = new RTViral(); + const steps = []; + for (let i = 1; i <= 5; i++) steps.push({ name: `SELECT id=${i}`, start: i, duration: 4 }); + const result = t.analyze({ steps }); + assert(result.hasNPlusOne); +}); + +test('api: exportSpeedscope / exportSpeedscopeJson', () => { + const t = new RTViral(); + const trace = { startTime: 0, duration: 10, steps: [{ name: 'a', start: 0, duration: 10 }] }; + assertEqual(t.exportSpeedscope(trace).profiles[0].type, 'evented'); + assert(typeof t.exportSpeedscopeJson(trace) === 'string'); +}); + +test('api: toShareableHtml and toMarkdown', () => { + const t = new RTViral(); + const trace = { method: 'GET', path: '/x', startTime: 0, duration: 10, status: 200, steps: [] }; + assert(t.toShareableHtml(trace).startsWith('')); + assert(t.toMarkdown(trace).includes('
')); +}); + +test('api: diff and diffToMarkdown', () => { + const t = new RTViral(); + const a = mkTrace(100, [{ name: 'q', start: 0, duration: 40 }]); + const b = mkTrace(180, [{ name: 'q', start: 0, duration: 120 }]); + assertEqual(t.diff(a, b, { regressionPercent: 10 }).regressed, true); + assert(t.diffToMarkdown(a, b).includes('Trace diff')); +}); + +test('api: buildExplainPrompt returns system+user', () => { + const t = new RTViral(); + const p = t.buildExplainPrompt(mkTrace(10, [{ name: 'x', start: 0, duration: 10 }])); + assert(p.system && p.user); +}); + +test('api: timeline summary now includes N+1 fields', () => { + const t = new RTViral(); + const steps = []; + for (let i = 1; i <= 5; i++) steps.push({ name: `SELECT id=${i}`, start: i, duration: 4 }); + const report = t.timeline({ requestId: 'r', method: 'GET', path: '/n', startTime: 0, duration: 30, status: 200, steps }); + assertEqual(report.summary.hasNPlusOne, true); + assert(Array.isArray(report.summary.nPlusOne)); + assert(report.summary.duplicates.length >= 1); +}); + +test('api: renderTimeline includes N+1 warning line', () => { + const t = new RTViral(); + const steps = []; + for (let i = 1; i <= 5; i++) steps.push({ name: `SELECT id=${i}`, start: i, duration: 4 }); + const text = t.renderTimeline({ method: 'GET', path: '/n', startTime: 0, duration: 30, status: 200, steps }, { ascii: true }); + assert(text.includes('N+1 detected')); +}); + +test('api: init with autoInstrument enables and destroy disables', () => { + const t = new RTViral(); + t.init({ autoInstrument: true }); + assert(Array.isArray(t._autoInstrumented)); + t.destroy(); + assertEqual(t._autoInstrumented.length, 0); +}); + +// ========================================================================= +// routes.js โ€” new export endpoints +// ========================================================================= +const { createRouter: createRouterV } = require('../lib/routes'); + +function mockResV() { + const r = { _status: 0, _headers: {}, _body: '' }; + r.writeHead = (code, headers) => { r._status = code; Object.assign(r._headers, headers || {}); }; + r.end = (data) => { r._body = data || ''; }; + r.statusCode = 200; + return r; +} + +function tracerWithTraces() { + const { RequestTracer } = require('../index'); + const t = new RequestTracer(); + t.init(); + const mk = (id, dur, qDur) => t.storage.store({ + requestId: id, method: 'GET', path: '/u', startTime: 1000, duration: dur, status: 200, + steps: [{ name: 'SELECT WHERE id = 1', start: 1000, duration: qDur, type: 'db' }], + }); + mk('rv_a', 100, 40); + mk('rv_b', 200, 120); + return t; +} + +test('routes: /trace/:id/speedscope returns evented profile', () => { + const t = tracerWithTraces(); + const res = mockResV(); + createRouterV(t)({ url: '/trace/rv_a/speedscope' }, res); + assertEqual(res._status, 200); + assertEqual(JSON.parse(res._body).profiles[0].type, 'evented'); + t.destroy(); +}); + +test('routes: /trace/:id/speedscope 404 for missing', () => { + const t = tracerWithTraces(); + const res = mockResV(); + createRouterV(t)({ url: '/trace/nope/speedscope' }, res); + assertEqual(res._status, 404); + t.destroy(); +}); + +test('routes: /trace/:id/markdown returns markdown', () => { + const t = tracerWithTraces(); + const res = mockResV(); + createRouterV(t)({ url: '/trace/rv_a/markdown' }, res); + assertEqual(res._status, 200); + assert(res._headers['Content-Type'].includes('text/markdown')); + assert(res._body.includes('
')); + t.destroy(); +}); + +test('routes: /trace/:id/markdown 404 for missing', () => { + const t = tracerWithTraces(); + const res = mockResV(); + createRouterV(t)({ url: '/trace/nope/markdown' }, res); + assertEqual(res._status, 404); + t.destroy(); +}); + +test('routes: /trace/:id/snapshot returns downloadable html', () => { + const t = tracerWithTraces(); + const res = mockResV(); + createRouterV(t)({ url: '/trace/rv_a/snapshot' }, res); + assertEqual(res._status, 200); + assert(res._headers['Content-Disposition'].includes('rv_a.html')); + assert(res._body.startsWith('')); + t.destroy(); +}); + +test('routes: /trace/:id/snapshot 404 for missing', () => { + const t = tracerWithTraces(); + const res = mockResV(); + createRouterV(t)({ url: '/trace/nope/snapshot' }, res); + assertEqual(res._status, 404); + t.destroy(); +}); + +test('routes: /trace/diff/:a/:b returns diff json', () => { + const t = tracerWithTraces(); + const res = mockResV(); + createRouterV(t)({ url: '/trace/diff/rv_a/rv_b' }, res); + assertEqual(res._status, 200); + const d = JSON.parse(res._body); + assertEqual(d.totalDeltaMs, 100); + t.destroy(); +}); + +test('routes: /trace/diff 404 when a trace missing', () => { + const t = tracerWithTraces(); + const res = mockResV(); + createRouterV(t)({ url: '/trace/diff/rv_a/nope' }, res); + assertEqual(res._status, 404); + t.destroy(); +}); + +// ========================================================================= +// explain.js โ€” LLM call paths (mocked fetch) +// ========================================================================= +test('explain: explainTrace calls fetch and returns content', async () => { + const savedFetch = global.fetch; + const savedKey = process.env.OPENAI_API_KEY; + let captured = null; + global.fetch = async (url, opts) => { + captured = { url, opts }; + return { + ok: true, + json: async () => ({ choices: [{ message: { content: ' do batching ' } }] }), + }; + }; + const out = await explain.explainTrace(mkTrace(50, [{ name: 'x', start: 0, duration: 50 }]), { + apiKey: 'test-key', model: 'm', baseUrl: 'https://example.com/v1/', + }); + assertEqual(out, 'do batching'); + assert(captured.url === 'https://example.com/v1/chat/completions'); + assert(captured.opts.headers.Authorization === 'Bearer test-key'); + global.fetch = savedFetch; + if (savedKey) process.env.OPENAI_API_KEY = savedKey; +}); + +test('explain: explainTrace throws on non-ok response', async () => { + const savedFetch = global.fetch; + global.fetch = async () => ({ ok: false, status: 500, text: async () => 'boom' }); + let threw = false; + try { + await explain.explainTrace(mkTrace(10, []), { apiKey: 'k' }); + } catch (err) { + threw = true; + assert(err.message.includes('HTTP 500')); + } + global.fetch = savedFetch; + assert(threw); +}); + +test('explain: prompt includes errors and gaps when present', () => { + const trace = { + method: 'GET', path: '/g', startTime: 0, duration: 200, status: 500, + steps: [{ name: 'fail', start: 0, duration: 10, error: 'nope' }], + }; + const { user } = explain.buildExplainPrompt(trace); + assert(user.includes('errored')); + assert(user.includes('untraced gap')); +}); + +// ========================================================================= +// auto-instrument.js โ€” mocked driver patching +// ========================================================================= +test('auto-instrument: enableAutoInstrumentation honors only filter', () => { + const applied = autoInstrument.enableAutoInstrumentation({ only: ['knex'] }); + assert(Array.isArray(applied)); + assert(applied.every(n => n === 'knex')); + autoInstrument.disableAutoInstrumentation(); +}); + +test('auto-instrument: knex instance without .on is returned untouched', () => { + const fake = {}; + assertEqual(autoInstrument.instrumentKnexInstance(fake), fake); +}); + +test('auto-instrument: prisma middleware records errors', async () => { + let registered = null; + autoInstrument.instrumentPrismaClient({ $use(fn) { registered = fn; } }); + const trace = { steps: [] }; + let threw = false; + await rwtAI(trace, async () => { + try { + await registered({ model: 'User', action: 'create' }, async () => { throw new Error('dup'); }); + } catch (_) { threw = true; } + }); + assert(threw); + assertEqual(trace.steps[0].error, 'dup'); +}); + +test('auto-instrument: disable is idempotent', () => { + autoInstrument.disableAutoInstrumentation(); + autoInstrument.disableAutoInstrumentation(); + assert(true); +}); + +test('auto-instrument: pg query is timed (promise + callback)', async () => { + class Client { query() { return Promise.resolve({ rows: [] }); } } + autoInstrument.__setRequireForTests((name) => (name === 'pg' ? { Client } : null)); + const applied = autoInstrument.enableAutoInstrumentation({ only: ['pg'] }); + assertEqual(applied[0], 'pg'); + const trace = { steps: [] }; + await rwtAI(trace, async () => { + const c = new Client(); + await c.query('SELECT * FROM users WHERE id = 1'); + await c.query({ text: 'SELECT 2' }); + }); + assertEqual(trace.steps.length, 2); + assert(trace.steps[0].name.startsWith('pg ')); + autoInstrument.disableAutoInstrumentation(); + autoInstrument.__setRequireForTests(null); +}); + +test('auto-instrument: pg callback style records step', () => { + class Client { query(sql, cb) { cb(null, { rows: [] }); } } + autoInstrument.__setRequireForTests((name) => (name === 'pg' ? { Client } : null)); + autoInstrument.enableAutoInstrumentation({ only: ['pg'] }); + const trace = { steps: [] }; + rwtAI(trace, () => { + const c = new Client(); + c.query('SELECT 1', () => {}); + }); + assertEqual(trace.steps.length, 1); + autoInstrument.disableAutoInstrumentation(); + autoInstrument.__setRequireForTests(null); +}); + +test('auto-instrument: mongodb collection methods are timed', async () => { + class Collection { + constructor() { this.collectionName = 'users'; } + find() { return { toArray: () => Promise.resolve([]) }; } + findOne() { return Promise.resolve(null); } + insertOne() { return Promise.resolve({}); } + insertMany() { return Promise.resolve({}); } + updateOne() { return Promise.resolve({}); } + updateMany() { return Promise.resolve({}); } + deleteOne() { return Promise.resolve({}); } + deleteMany() { return Promise.resolve({}); } + aggregate() { return { toArray: () => Promise.resolve([]) }; } + countDocuments() { return Promise.resolve(0); } + } + autoInstrument.__setRequireForTests((name) => (name === 'mongodb' ? { Collection } : null)); + const applied = autoInstrument.enableAutoInstrumentation({ only: ['mongodb'] }); + assertEqual(applied[0], 'mongodb'); + const trace = { steps: [] }; + await rwtAI(trace, async () => { + const col = new Collection(); + col.find({}); // cursor (sync timed) + await col.findOne({}); // promise timed + await col.insertOne({}); + }); + assert(trace.steps.length >= 3); + assert(trace.steps.some(s => s.name.includes('mongo users.find'))); + autoInstrument.disableAutoInstrumentation(); + autoInstrument.__setRequireForTests(null); +}); + +test('auto-instrument: ioredis sendCommand is timed', async () => { + class Redis { sendCommand() { return Promise.resolve('OK'); } } + autoInstrument.__setRequireForTests((name) => (name === 'ioredis' ? Redis : null)); + const applied = autoInstrument.enableAutoInstrumentation({ only: ['redis'] }); + assertEqual(applied[0], 'redis'); + const trace = { steps: [] }; + await rwtAI(trace, async () => { + const r = new Redis(); + await r.sendCommand({ name: 'get' }); + }); + assertEqual(trace.steps.length, 1); + assert(trace.steps[0].name === 'redis GET'); + autoInstrument.disableAutoInstrumentation(); + autoInstrument.__setRequireForTests(null); +}); + +test('auto-instrument: recordStep is a no-op without active trace', () => { + class Client { query() { return Promise.resolve({}); } } + autoInstrument.__setRequireForTests((name) => (name === 'pg' ? { Client } : null)); + autoInstrument.enableAutoInstrumentation({ only: ['pg'] }); + // No runWithTrace wrapper -> no active trace -> should not throw + const c = new Client(); + c.query('SELECT 1'); + assert(true); + autoInstrument.disableAutoInstrumentation(); + autoInstrument.__setRequireForTests(null); +}); + // Run all tests run();