From d3b31a0e29a67c8d3a2b756ec46744c27f70ea8f Mon Sep 17 00:00:00 2001 From: Dhruvilkumar Ashokbhai Chodvadiya <50516925+dhruvac29@users.noreply.github.com> Date: Tue, 27 Oct 2026 20:53:29 -0700 Subject: [PATCH] feat(cli): report opt-in command timings (#7042) * feat(cli): report opt-in command timings * fix(cli): time standalone MCP doctor * fix(cli): retain timing on doctor errors * fix(cli): preserve formatted version output with command timings --------- Co-authored-by: dhruvac29 Co-authored-by: gensokyo-dev <342580529+gensokyo-dev@users.noreply.github.com> --- docs/cli.md | 9 +++ scripts/rea.mjs | 37 ++++++++--- src/cli.ts | 32 +++++++++- src/cliBuiltinArguments.ts | 6 +- src/cliOutput.ts | 6 +- tests/acceptance/cliTimings.test.ts | 68 +++++++++++++++++++++ tests/boundary/cli/mcpDoctorHelpCli.test.ts | 35 +++++++++++ 7 files changed, 178 insertions(+), 15 deletions(-) create mode 100644 tests/acceptance/cliTimings.test.ts diff --git a/docs/cli.md b/docs/cli.md index 6e74c14fa2..c08c46a19a 100644 --- a/docs/cli.md +++ b/docs/cli.md @@ -51,6 +51,15 @@ module page. See [JavaScript application workflows](javascript-application-workflows.md) for views, feature traces and comparisons that take the same saved Evidence. +Add `--timings` to a command to write one JSON timing record to stderr. For +example, `rea inspect-elf-notes program --json --timings > result.json` keeps +stdout as a parseable result and writes +`{"rea_timings":{"version":1,"command_ms":42}}` to stderr. `command_ms` +measures CLI command dispatch and result delivery; it is not provider-only or +analysis-only time. The flag is off by default, and the record omits stages +that REA did not measure. Root version reporting does not dispatch a command +and has no command timing record. + ## JSON Lines record output Use `--format jsonl` to consume row-oriented results one record per line: diff --git a/scripts/rea.mjs b/scripts/rea.mjs index 15fc98c9a5..71006980a7 100755 --- a/scripts/rea.mjs +++ b/scripts/rea.mjs @@ -68,15 +68,34 @@ if (!(await compiledRuntimeExists(runtimeFiles))) { await runMcpHttpEntrypoint(args.slice(1)); } else if (isMcpDoctorMode) { guardClosedStdout(); - const { runProductionMcpDoctorCli } = - await import("../dist/cli-runtime/mcpDoctor.js"); - const result = await runProductionMcpDoctorCli(doctorArguments, { - dispatcherPath: fileURLToPath(import.meta.url), - packageRoot, - stdoutIsTerminal: process.stdout.isTTY === true, - }); - writeStdout(result.output); - process.exitCode = result.exitCode; + // Doctor runs outside Incur, so handle its global timing flag here. Keep a + // token consumed by --format as a value, even when it looks like a flag. + const outputValues = new Set( + builtinArguments + .splitIncurBuiltinArguments(doctorArguments) + .outputValues.map(({ index }) => index), + ); + const doctorCliArguments = doctorArguments.filter( + (argument, index) => argument !== "--timings" || outputValues.has(index), + ); + const timingRequested = doctorCliArguments.length !== doctorArguments.length; + const started = performance.now(); + try { + const { runProductionMcpDoctorCli } = + await import("../dist/cli-runtime/mcpDoctor.js"); + const result = await runProductionMcpDoctorCli(doctorCliArguments, { + dispatcherPath: fileURLToPath(import.meta.url), + packageRoot, + stdoutIsTerminal: process.stdout.isTTY === true, + }); + writeStdout(result.output); + process.exitCode = result.exitCode; + } finally { + if (timingRequested) + process.stderr.write( + `${JSON.stringify({ rea_timings: { version: 1, command_ms: Math.round(performance.now() - started) } })}\n`, + ); + } } else { const { cliConfigurationError, diff --git a/src/cli.ts b/src/cli.ts index 5b9dfcff87..ffddd278db 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -19,7 +19,7 @@ import { registerAnalysisViewCommands } from "./cli/analysisViewCommands.js"; import { registerBinaryDiagnosticsCommands } from "./cli/binaryDiagnosticsCommands.js"; import { registerFridaCommands } from "./cli/fridaCommands.js"; import type { FridaInstrumentationPort } from "./application/frida/FridaInstrumentationPort.js"; -import { Cli } from "incur"; +import { Cli, z } from "incur"; import { adaptCliOutputArgumentsForIncur, normalizeCliArguments, @@ -95,9 +95,15 @@ export const createCli = ( "cli", level?.ok === true ? level.value : "silent", ); - const cli = Cli.create(PRODUCT_IDENTITY.cliBinary, { + const timedCli = Cli.create(PRODUCT_IDENTITY.cliBinary, { version: PRODUCT_IDENTITY.packageVersion, description: "Reverse engineer anything from your terminal or agent.", + globals: z.object({ + timings: z + .boolean() + .default(false) + .describe("Write measured command timing to stderr."), + }), mcp: { command: npxRegistrationCommand().join(" "), instructions: @@ -115,6 +121,23 @@ export const createCli = ( }, }); + timedCli.use(async (context, next) => { + if (!context.globals.timings) return next(); + const started = performance.now(); + try { + await next(); + } finally { + // This interval covers CLI command dispatch, including result delivery. + // It is not a provider-only or analysis-only measurement. + process.stderr.write( + `${JSON.stringify({ rea_timings: { version: 1, command_ms: Math.round(performance.now() - started) } })}\n`, + ); + } + }); + // Command registrars do not inspect global options; preserve their existing + // type while Incur owns parsing and the middleware owns this added flag. + const cli = timedCli as unknown as CliInstance; + registerSetupCommands(cli, logger, environment); registerReverseEngineeringCommands(cli, logger, environment); registerCutterCommands(cli, logger, environment); @@ -173,7 +196,10 @@ export const createCli = ( presentCliArgumentErrors(cli); const serveDeclared = excludeDeclaredSensitiveArguments(cli); const serve = cli.serve.bind(cli); - const complete = createCliCompletions(cli, environment); + const complete = createCliCompletions( + cli as unknown as Parameters[0], + environment, + ); cli.serve = (arguments_ = process.argv.slice(2), options) => complete(arguments_, options ?? {}) ? Promise.resolve() diff --git a/src/cliBuiltinArguments.ts b/src/cliBuiltinArguments.ts index 672f66126d..215e4fa9aa 100644 --- a/src/cliBuiltinArguments.ts +++ b/src/cliBuiltinArguments.ts @@ -11,6 +11,7 @@ export const OUTPUT_SWITCHES: ReadonlySet = new Set([ "--json", "--full-output", "--token-count", + "--timings", ]); /** Valueless flags Incur removes from every position before command parsing. */ @@ -27,6 +28,7 @@ export const INCUR_BUILTIN_FLAGS: ReadonlySet = new Set([ "--schema", "--json", "--token-count", + "--timings", ]); /** Command tokens and output-flag values as Incur's builtin pass assigns them. */ @@ -42,8 +44,8 @@ export interface IncurBuiltinArgumentSplit { /** * Mirror Incur's builtin pass over normalized arguments without stopping at a - * rejected value, so callers can still see every later token. REA configures - * neither a config flag nor global options, which Incur would also remove. + * rejected value, so callers can still see every later token. REA's boolean + * timing global follows the same valueless pass; no config flag is registered. */ export const splitIncurBuiltinArguments = ( arguments_: readonly string[], diff --git a/src/cliOutput.ts b/src/cliOutput.ts index c6516b93b6..a3a1f26433 100644 --- a/src/cliOutput.ts +++ b/src/cliOutput.ts @@ -180,7 +180,11 @@ export const parseCliOutputArguments = ( const next = arguments_[index + 1]; if (next === undefined || next.startsWith("-")) rootVersion = true; else versionEligible = false; - } else if (argument !== "--json" && argument !== "--format") + } else if ( + argument !== "--json" && + argument !== "--format" && + argument !== "--timings" + ) versionEligible = false; // Incur scans builtins across `--` and reads spaced value forms, which // normalizeCliArguments has produced. Mirror those effective values. diff --git a/tests/acceptance/cliTimings.test.ts b/tests/acceptance/cliTimings.test.ts new file mode 100644 index 0000000000..ac7cbd9ef1 --- /dev/null +++ b/tests/acceptance/cliTimings.test.ts @@ -0,0 +1,68 @@ +import { writeFile } from "node:fs/promises"; +import { join } from "node:path"; +import { expect } from "vitest"; + +import { elfNoteFixture } from "../../src/native/elf/ElfNotes.fixture.js"; +import { createTestTempDirectory } from "../fixtures/temporaryDirectory.js"; +import { cliTest } from "../support/cli/cliFixture.js"; + +const timingRecord = (stderr: string) => { + const lines = stderr.trim().split("\n"); + expect(lines).toHaveLength(1); + const record: unknown = JSON.parse(lines[0]!); + expect(record).toMatchObject({ + rea_timings: { version: 1, command_ms: expect.any(Number) }, + }); + const duration = (record as { rea_timings: { command_ms: number } }) + .rea_timings.command_ms; + expect(Number.isFinite(duration)).toBe(true); + expect(duration).toBeGreaterThanOrEqual(0); +}; + +cliTest( + "writes opt-in command timing to stderr after success and failure without changing JSON stdout", + async ({ cli }) => { + const root = await createTestTempDirectory("rea-cli-timings-"); + const valid = join(root, "program"); + const invalid = join(root, "truncated"); + await writeFile(valid, elfNoteFixture({ ownership: "program" })); + await writeFile(invalid, Buffer.from("ELF")); + + const defaultRun = await cli.run({ + arguments: ["inspect-elf-notes", valid, "--json"], + }); + expect(defaultRun.exitCode, defaultRun.stderr).toBe(0); + expect(defaultRun.stderr).not.toContain("rea_timings"); + + const successful = await cli.run({ + arguments: ["--timings", "inspect-elf-notes", valid, "--json"], + }); + expect(successful.exitCode, successful.stderr).toBe(0); + expect(successful.json).toMatchObject({ + normalized_result: { coverage: { status: "complete" } }, + }); + timingRecord(successful.stderr); + + const failed = await cli.run({ + arguments: ["inspect-elf-notes", invalid, "--json", "--timings"], + }); + expect(failed.exitCode).toBe(1); + expect(failed.json).toMatchObject({ code: "invalid_request" }); + timingRecord(failed.stderr); + }, +); + +cliTest( + "preserves formatted root version output when timings are requested", + async ({ cli }) => { + const plain = await cli.run({ arguments: ["--version", "--json"] }); + const timed = await cli.run({ + arguments: ["--timings", "--version", "--json"], + }); + expect(plain.exitCode).toBe(0); + expect(plain.json).toBeTypeOf("object"); + expect(timed.exitCode).toBe(0); + expect(timed.stdout).toBe(plain.stdout); + expect(timed.stderr).toBe(""); + }, +); diff --git a/tests/boundary/cli/mcpDoctorHelpCli.test.ts b/tests/boundary/cli/mcpDoctorHelpCli.test.ts index 1ad07f5032..1d5f0cdeac 100644 --- a/tests/boundary/cli/mcpDoctorHelpCli.test.ts +++ b/tests/boundary/cli/mcpDoctorHelpCli.test.ts @@ -117,4 +117,39 @@ describe("MCP doctor help boundary", () => { }, CLI_INTEGRATION_TIMEOUT_MS, ); + + workspaceCliTest( + "reports doctor timing on stderr while preserving JSON output", + async ({ cli }) => { + const result = await cli.run({ + arguments: ["mcp", "doctor", "--json", "--timings"], + }); + expect([0, 1]).toContain(result.exitCode); + expect(JSON.parse(result.stdout)).toHaveProperty("healthy"); + const lines = result.stderr.trim().split("\n"); + expect(lines).toHaveLength(1); + const record: unknown = JSON.parse(lines[0]!); + expect(record).toMatchObject({ + rea_timings: { version: 1, command_ms: expect.any(Number) }, + }); + const duration = (record as { rea_timings: { command_ms: number } }) + .rea_timings.command_ms; + expect(Number.isFinite(duration)).toBe(true); + expect(duration).toBeGreaterThanOrEqual(0); + }, + CLI_INTEGRATION_TIMEOUT_MS, + ); + + workspaceCliTest( + "does not treat a --format value as the timing flag", + async ({ cli }) => { + const result = await cli.run({ + arguments: ["mcp", "doctor", "--format", "--timings"], + }); + expect(result.exitCode).toBe(1); + expect(result.stdout).toContain("Invalid output format: --timings"); + expect(result.stderr).toBe(""); + }, + CLI_INTEGRATION_TIMEOUT_MS, + ); });