From 39ea0cb74534ecfd79e81c3ec15652ea18a63306 Mon Sep 17 00:00:00 2001 From: cryptotavares Date: Fri, 23 Oct 2026 14:17:40 +0100 Subject: [PATCH 1/2] feat: add meta.timing to every daemon response Every /tool/*, /launch and /cleanup response body now ends with `meta: { timing: { queueMs, toolMs, observationMs, totalMs } }`, on success and on errors (404, 400 validation, platform gate, 500 tool throw, 500 from the error middleware for malformed JSON). The request start is taken before the body parser, so totalMs covers request in to response out. The mm CLI keeps `meta` as the last key of its JSON output. String results are printed as before, without meta. Add scripts/bench.mjs (not shipped) to run mm commands N times against a live session and print median/p95 of wall clock, bytes and meta.timing. --- scripts/bench.mjs | 173 +++++++++++++++++++++++++++++ src/cli/mm.test.ts | 80 +++++++++++++ src/cli/mm.ts | 14 ++- src/server/create-server.test.ts | 160 ++++++++++++++++++++++++++ src/server/create-server.ts | 132 +++++++++++++++------- src/server/response-timing.test.ts | 113 +++++++++++++++++++ src/server/response-timing.ts | 130 ++++++++++++++++++++++ src/types/http.ts | 24 ++++ 8 files changed, 784 insertions(+), 42 deletions(-) create mode 100644 scripts/bench.mjs create mode 100644 src/server/response-timing.test.ts create mode 100644 src/server/response-timing.ts diff --git a/scripts/bench.mjs b/scripts/bench.mjs new file mode 100644 index 0000000..1855ca4 --- /dev/null +++ b/scripts/bench.mjs @@ -0,0 +1,173 @@ +#!/usr/bin/env node +/* eslint-disable import-x/no-nodejs-modules */ +// Benchmark `mm` commands against a running session (not shipped). +// +// Usage (run from the consumer worktree that owns the session): +// node /scripts/bench.mjs [--runs N] [--mm ""] -- [ ...] +// +// Each is one mm invocation, quoted if it has arguments: +// node bench.mjs --runs 5 -- describe-screen get-state \ +// "cdp Runtime.evaluate '{\"expression\":\"1+1\"}'" +// +// Prints TSV to stdout: median and p95 (nearest rank; with 5 runs p95 is the +// max) of wall clock, response bytes and meta.timing.{queueMs,toolMs, +// observationMs,totalMs}. Wall clock includes the `--mm` launcher start-up +// (about 1 s for `yarn mm`). Runs that exit non-zero, time out (--timeout-ms, +// default 180000) or are killed count in `fail` and are left out of the stats. + +import { Buffer } from 'node:buffer'; +import { spawnSync } from 'node:child_process'; +import process from 'node:process'; + +const USAGE = + 'usage: bench.mjs [--runs N] [--timeout-ms MS] [--mm ""] -- [ ...]'; + +/** + * Parses the command line. + * + * @param {string[]} argv - Arguments after the script name. + * @returns {{ runs: number, timeoutMs: number, mm: string, commands: string[] }} The options. + */ +function parseArgs(argv) { + let runs = 5; + let timeoutMs = 180_000; + let mm = 'yarn mm'; + const sep = argv.indexOf('--'); + const opts = sep === -1 ? argv : argv.slice(0, sep); + const commands = sep === -1 ? [] : argv.slice(sep + 1); + for (let i = 0; i < opts.length; i++) { + const flag = opts[i]; + const value = opts[i + 1]; + if (flag === '--runs' && value) { + runs = Number(value); + i += 1; + } else if (flag === '--timeout-ms' && value) { + timeoutMs = Number(value); + i += 1; + } else if (flag === '--mm' && value) { + mm = value; + i += 1; + } else { + throw new Error(`unknown option ${flag}\n${USAGE}`); + } + } + if (!Number.isInteger(runs) || runs < 1) { + throw new Error(`--runs must be a positive integer\n${USAGE}`); + } + if (!Number.isInteger(timeoutMs) || timeoutMs < 1) { + throw new Error(`--timeout-ms must be a positive integer\n${USAGE}`); + } + if (commands.length === 0) { + throw new Error(USAGE); + } + return { runs, timeoutMs, mm, commands }; +} + +/** + * Returns a quantile (nearest rank) of a list of numbers. + * + * @param {number[]} values - The samples. + * @param {number} fraction - Quantile in [0, 1]. + * @returns {number | string} The quantile, or '-' when there are no samples. + */ +function quantile(values, fraction) { + if (values.length === 0) { + return '-'; + } + const sorted = [...values].sort((a, b) => a - b); + const rank = Math.max(1, Math.ceil(fraction * sorted.length)); + return Math.round(sorted[rank - 1]); +} + +/** + * Runs one mm command once. + * + * @param {string} mm - The mm invocation (for example `yarn mm`). + * @param {string} command - The command and its arguments. + * @param {number} timeoutMs - Kill the run after this many milliseconds. + * @returns {{ ok: boolean, wallMs: number, bytes: number, timing?: Record }} The run result. + */ +function runOnce(mm, command, timeoutMs) { + const start = performance.now(); + const proc = spawnSync(`${mm} ${command}`, { + shell: true, + encoding: 'utf8', + maxBuffer: 64 * 1024 * 1024, + timeout: timeoutMs, + }); + const wallMs = performance.now() - start; + const stdout = proc.stdout ?? ''; + let timing; + try { + timing = JSON.parse(stdout)?.meta?.timing; + } catch { + // string output or not JSON: no timing + } + return { + ok: proc.status === 0 && !proc.error && !proc.signal, + wallMs, + bytes: Buffer.byteLength(stdout), + timing, + }; +} + +const FIELDS = ['queueMs', 'toolMs', 'observationMs', 'totalMs']; + +/** + * Entry point. + */ +function main() { + let options; + try { + options = parseArgs(process.argv.slice(2)); + } catch (error) { + process.stderr.write(`${error.message}\n`); + process.exit(2); + } + const { runs, timeoutMs, mm, commands } = options; + + const header = ['command', 'runs', 'fail', 'wall_p50', 'wall_p95']; + header.push('bytes_p50'); + for (const field of FIELDS) { + header.push(`${field}_p50`, `${field}_p95`); + } + process.stdout.write(`${header.join('\t')}\n`); + + for (const command of commands) { + const results = []; + for (let i = 0; i < runs; i++) { + const result = runOnce(mm, command, timeoutMs); + results.push(result); + process.stderr.write( + `${command} #${i + 1}: ${Math.round(result.wallMs)}ms ${result.ok ? 'ok' : 'FAIL'}\n`, + ); + } + const ok = results.filter((result) => result.ok); + const row = [ + command.replace(/\s+/gu, ' '), + runs, + runs - ok.length, + quantile( + ok.map((result) => result.wallMs), + 0.5, + ), + quantile( + ok.map((result) => result.wallMs), + 0.95, + ), + quantile( + ok.map((result) => result.bytes), + 0.5, + ), + ]; + for (const field of FIELDS) { + const samples = ok + .map((result) => result.timing?.[field]) + .filter((value) => typeof value === 'number'); + row.push(quantile(samples, 0.5), quantile(samples, 0.95)); + } + process.stdout.write(`${row.join('\t')}\n`); + } +} + +main(); diff --git a/src/cli/mm.test.ts b/src/cli/mm.test.ts index 7c85363..9733fa6 100644 --- a/src/cli/mm.test.ts +++ b/src/cli/mm.test.ts @@ -1353,6 +1353,86 @@ describe('sendRequest', () => { observations: { state: 'home' }, }); }); + + describe('meta', () => { + const meta = { + timing: { queueMs: 0, toolMs: 12, observationMs: 30, totalMs: 45 }, + }; + + const printed = (): Record => + JSON.parse((stdoutSpy.mock.calls[0] as string[])[0]) as Record< + string, + unknown + >; + + it('prints meta after the result fields', async () => { + vi.spyOn(globalThis, 'fetch').mockResolvedValue({ + ok: true, + json: async () => ({ ok: true, result: { count: 2 }, meta }), + } as Response); + + await sendRequest(3000, 'POST', '/tool/get_state', {}); + + const output = printed(); + expect(output).toStrictEqual({ count: 2, meta }); + expect(Object.keys(output)).toStrictEqual(['count', 'meta']); + }); + + it('prints meta after observations', async () => { + vi.spyOn(globalThis, 'fetch').mockResolvedValue({ + ok: true, + json: async () => ({ + ok: true, + result: { clicked: true }, + observations: { state: 'home' }, + meta, + }), + } as Response); + + await sendRequest(3000, 'POST', '/tool/click', { a11yRef: 'e1' }); + + expect(Object.keys(printed())).toStrictEqual([ + 'clicked', + 'observations', + 'meta', + ]); + }); + + it('does not print meta for string results', async () => { + vi.spyOn(globalThis, 'fetch').mockResolvedValue({ + ok: true, + json: async () => ({ ok: true, result: 'simple string', meta }), + } as Response); + + await sendRequest(3000, 'GET', '/status', null); + + expect(stdoutSpy).toHaveBeenCalledWith('simple string\n'); + }); + + it('wraps array results so meta can be printed', async () => { + vi.spyOn(globalThis, 'fetch').mockResolvedValue({ + ok: true, + json: async () => ({ ok: true, result: [1, 2], meta }), + } as Response); + + await sendRequest(3000, 'POST', '/tool/get_state', {}); + + expect(printed()).toStrictEqual({ result: [1, 2], meta }); + }); + + it('prints meta once when the body has no result key', async () => { + vi.spyOn(globalThis, 'fetch').mockResolvedValue({ + ok: true, + json: async () => ({ ok: true, status: 'running', meta }), + } as Response); + + await sendRequest(3000, 'GET', '/status', null); + + const output = printed(); + expect(output).toStrictEqual({ ok: true, status: 'running', meta }); + expect(Object.keys(output).at(-1)).toBe('meta'); + }); + }); }); describe('routeCommand', () => { diff --git a/src/cli/mm.ts b/src/cli/mm.ts index ebf8f46..97e0e35 100644 --- a/src/cli/mm.ts +++ b/src/cli/mm.ts @@ -1094,8 +1094,9 @@ export async function sendRequest( try { const data = await daemonFetch(port, method, requestPath, body, timeout); - const result = data.result ?? data; - const observations = data.observations as + const { meta, ...rest } = data; + const result = rest.result ?? rest; + const observations = rest.observations as | Record | undefined; let output: unknown = result; @@ -1106,6 +1107,15 @@ export async function sendRequest( : { result }; output = { ...base, observations }; } + if (meta !== undefined && typeof output !== 'string') { + const base = + typeof output === 'object' && + output !== null && + !Array.isArray(output) + ? (output as Record) + : { result: output }; + output = { ...base, meta }; + } if (typeof output === 'string') { process.stdout.write(`${output}\n`); } else { diff --git a/src/server/create-server.test.ts b/src/server/create-server.test.ts index 68416f7..32f5f0b 100644 --- a/src/server/create-server.test.ts +++ b/src/server/create-server.test.ts @@ -1335,6 +1335,166 @@ describe('createServer with active session', () => { expect(mockSM.getExtensionState).toHaveBeenCalledTimes(1); }); }); + + describe('meta.timing', () => { + type TimedBody = { + ok: boolean; + error?: { code: string }; + meta?: { + timing: { + queueMs: number; + toolMs: number; + observationMs: number; + totalMs: number; + }; + }; + }; + + const post = async ( + urlPath: string, + body: string = JSON.stringify({}), + ): Promise<{ status: number; body: TimedBody }> => { + const res = await httpRequest( + `http://127.0.0.1:${state.port}${urlPath}`, + { + method: 'POST', + headers: { 'Content-Type': 'application/json' }, + body, + }, + ); + return { status: res.status, body: (await res.json()) as TimedBody }; + }; + + const expectValidTiming = (body: TimedBody): void => { + const timing = body.meta?.timing; + expect(timing).toBeDefined(); + for (const value of Object.values(timing ?? {})) { + expect(Number.isInteger(value)).toBe(true); + expect(value).toBeGreaterThanOrEqual(0); + } + expect(timing?.totalMs).toBeGreaterThanOrEqual( + (timing?.queueMs ?? 0) + + (timing?.toolMs ?? 0) + + (timing?.observationMs ?? 0), + ); + }; + + it('adds meta.timing as the last key of a successful response', async () => { + const { status, body } = await post('/cleanup'); + + expect(status).toBe(200); + expect(body.ok).toBe(true); + expectValidTiming(body); + expect(Object.keys(body).at(-1)).toBe('meta'); + }); + + it('measures tool and observation time separately', async () => { + mockSM.cleanup.mockImplementationOnce( + async () => + new Promise((resolve) => setTimeout(() => resolve(true), 60)), + ); + mockSM.getExtensionState.mockImplementationOnce( + async () => + new Promise((resolve) => + setTimeout(() => resolve({ isLoaded: true, currentUrl: '' }), 60), + ), + ); + + const { body } = await post('/cleanup'); + + expectValidTiming(body); + expect(body.meta?.timing.toolMs).toBeGreaterThanOrEqual(50); + expect(body.meta?.timing.observationMs).toBeGreaterThanOrEqual(50); + }); + + it('reports observationMs 0 when no session is active', async () => { + mockSM.hasActiveSession.mockReturnValue(false); + + const { body } = await post('/tool/get_context'); + + expectValidTiming(body); + expect(body.meta?.timing.observationMs).toBe(0); + }); + + it('reports queue wait for a request queued behind another', async () => { + let releaseFirst!: () => void; + mockSM.cleanup.mockImplementationOnce( + async () => + new Promise((resolve) => { + releaseFirst = () => resolve(true); + }), + ); + + const first = post('/cleanup'); + // The first request is now running inside the queue. + await vi.waitFor(() => expect(mockSM.cleanup).toHaveBeenCalled()); + const second = post('/tool/get_context'); + await new Promise((resolve) => setTimeout(resolve, 60)); + releaseFirst(); + + const [firstRes, secondRes] = await Promise.all([first, second]); + expectValidTiming(firstRes.body); + expectValidTiming(secondRes.body); + expect(secondRes.body.meta?.timing.queueMs).toBeGreaterThanOrEqual(50); + }); + + it('includes meta.timing when the tool throws', async () => { + mockSM.cleanup.mockRejectedValueOnce(new Error('Browser crash')); + + const { status, body } = await post('/cleanup'); + + expect(status).toBe(500); + expect(body.error?.code).toBe('TOOL_EXECUTION_FAILED'); + expectValidTiming(body); + }); + + it('includes meta.timing on validation errors', async () => { + const { status, body } = await post('/tool/click'); + + expect(status).toBe(400); + expect(body.error?.code).toBe('VALIDATION_ERROR'); + expectValidTiming(body); + expect(body.meta?.timing.toolMs).toBe(0); + }); + + it('includes meta.timing for unknown tools', async () => { + const { status, body } = await post('/tool/nonexistent'); + + expect(status).toBe(404); + expectValidTiming(body); + }); + + it('includes meta.timing for platform gate errors', async () => { + const { status, body } = await post( + '/tool/device_swipe', + JSON.stringify({ direction: 'up' }), + ); + + expect(status).toBe(200); + expect(body.error?.code).toBe('MM_TOOL_NOT_SUPPORTED_ON_PLATFORM'); + expectValidTiming(body); + }); + + it('includes meta.timing for malformed JSON bodies, measured from request arrival', async () => { + // Each performance.now() call advances 25ms, so a start recorded before + // the body parser yields totalMs > 0 in the error middleware. + let clock = 0; + const nowSpy = vi + .spyOn(performance, 'now') + .mockImplementation(() => (clock += 25)); + + try { + const { status, body } = await post('/tool/get_state', '{not json'); + + expect(status).toBe(500); + expect(body.error?.code).toBe('INTERNAL_ERROR'); + expectValidTiming(body); + expect(body.meta?.timing.totalMs).toBeGreaterThan(0); + } finally { + nowSpy.mockRestore(); + } + }); + }); }); describe('createServer with logging', () => { diff --git a/src/server/create-server.ts b/src/server/create-server.ts index b039027..b00fe1a 100644 --- a/src/server/create-server.ts +++ b/src/server/create-server.ts @@ -7,6 +7,12 @@ import * as http from 'node:http'; import { writeDaemonState, removeDaemonState } from './daemon-state.js'; import { compactObservation } from './observation-compaction.js'; import { RequestQueue } from './request-queue.js'; +import { + RequestTimer, + requestStartOf, + setRequestStart, + withMeta, +} from './response-timing.js'; import pkg from '../../package.json'; import type { PortMap, WorkflowContext } from '../capabilities/context.js'; import type { ExtensionState } from '../capabilities/types.js'; @@ -265,6 +271,13 @@ export function createServer(config: ServerConfig): ServerInstance { let idleCheckInterval: ReturnType | null = null; let lastObservation: StepRecordObservation | null = null; + // Registered before the body parser so `meta.timing.totalMs` includes body + // parsing, and so malformed-JSON errors still have a start time. + app.use((_req, res, next) => { + setRequestStart(res, performance.now()); + next(); + }); + // eslint-disable-next-line import-x/no-named-as-default-member app.use(express.json({ limit: '10mb' })); @@ -399,23 +412,37 @@ export function createServer(config: ServerConfig): ServerInstance { rawInput: unknown, res: express.Response, ): Promise { + const timer = new RequestTimer(requestStartOf(res)); const tool = toolRegistry.get(toolName); if (!tool) { - res.status(404).json({ - ok: false, - error: { code: 'TOOL_NOT_FOUND', message: `Unknown tool: ${toolName}` }, - }); + res.status(404).json( + withMeta( + { + ok: false, + error: { + code: 'TOOL_NOT_FOUND', + message: `Unknown tool: ${toolName}`, + }, + }, + timer.meta(), + ), + ); return; } if (!workflowContext) { - res.status(503).json({ - ok: false, - error: { - code: 'SERVER_NOT_STARTED', - message: 'Server has not been started yet.', - }, - }); + res.status(503).json( + withMeta( + { + ok: false, + error: { + code: 'SERVER_NOT_STARTED', + message: 'Server has not been started yet.', + }, + }, + timer.meta(), + ), + ); return; } @@ -426,19 +453,24 @@ export function createServer(config: ServerConfig): ServerInstance { if (schema) { const parsed = schema.safeParse(rawInput); if (!parsed.success) { - res.status(400).json({ - ok: false, - error: { - code: 'VALIDATION_ERROR', - message: parsed.error.issues - .map((i) => - i.path.length > 0 - ? `${i.path.join('.')}: ${i.message}` - : i.message, - ) - .join('; '), - }, - }); + res.status(400).json( + withMeta( + { + ok: false, + error: { + code: 'VALIDATION_ERROR', + message: parsed.error.issues + .map((i) => + i.path.length > 0 + ? `${i.path.join('.')}: ${i.message}` + : i.message, + ) + .join('; '), + }, + }, + timer.meta(), + ), + ); return; } validatedInput = parsed.data; @@ -454,7 +486,7 @@ export function createServer(config: ServerConfig): ServerInstance { config.sessionManager.getPlatformDriver?.()?.getPlatform(), ); if (gateError) { - res.json({ ok: false, error: gateError }); + res.json(withMeta({ ok: false, error: gateError }, timer.meta())); return; } @@ -466,10 +498,13 @@ export function createServer(config: ServerConfig): ServerInstance { : undefined; try { + timer.markEnqueued(); const { toolResult, observations } = await queue.enqueue( async () => { + timer.markTaskStart(); const context = buildToolContext(currentWorkflowContext); const result = await tool(validatedInput, context); + timer.markToolEnd(); let obs: StepRecordObservation | undefined; if ( @@ -479,6 +514,7 @@ export function createServer(config: ServerConfig): ServerInstance { ) && config.sessionManager.hasActiveSession() ) { + timer.markObservationStart(); try { obs = await Promise.race([ (async (): Promise => { @@ -566,6 +602,7 @@ export function createServer(config: ServerConfig): ServerInstance { } catch { // non-fatal: observation failure must not block the tool response } + timer.markObservationEnd(); } return { toolResult: result, observations: obs }; @@ -591,7 +628,12 @@ export function createServer(config: ServerConfig): ServerInstance { includeInResponse && observations ? compactObservation(observations, lastObservation) : undefined; - res.json(buildResponseBody(toolResult, responseObservations)); + res.json( + withMeta( + buildResponseBody(toolResult, responseObservations), + timer.meta(), + ), + ); if ( toolName === 'describe_screen' || @@ -618,13 +660,18 @@ export function createServer(config: ServerConfig): ServerInstance { startTime, ); - res.status(500).json({ - ok: false, - error: { - code: 'TOOL_EXECUTION_FAILED', - message: extractErrorMessage(error), - }, - }); + res.status(500).json( + withMeta( + { + ok: false, + error: { + code: 'TOOL_EXECUTION_FAILED', + message: extractErrorMessage(error), + }, + }, + timer.meta(), + ), + ); } } @@ -651,13 +698,18 @@ export function createServer(config: ServerConfig): ServerInstance { _next: express.NextFunction, ) => { appendLog(config.logFilePath, `[ERROR] ${error.message}`); - res.status(500).json({ - ok: false, - error: { - code: 'INTERNAL_ERROR', - message: error.message, - }, - }); + res.status(500).json( + withMeta( + { + ok: false, + error: { + code: 'INTERNAL_ERROR', + message: error.message, + }, + }, + new RequestTimer(requestStartOf(res)).meta(), + ), + ); }, ); diff --git a/src/server/response-timing.test.ts b/src/server/response-timing.test.ts new file mode 100644 index 0000000..6fb9bb1 --- /dev/null +++ b/src/server/response-timing.test.ts @@ -0,0 +1,113 @@ +import { afterEach, describe, expect, it, vi } from 'vitest'; + +import { RequestTimer, withMeta } from './response-timing.js'; + +describe('RequestTimer', () => { + let now = 0; + + afterEach(() => { + vi.restoreAllMocks(); + }); + + const useFakeClock = (start: number): void => { + now = start; + vi.spyOn(performance, 'now').mockImplementation(() => now); + }; + + it('reports zeros for phases that never started', () => { + useFakeClock(1000); + const timer = new RequestTimer(); + now = 1012.4; + + expect(timer.snapshot()).toStrictEqual({ + queueMs: 0, + toolMs: 0, + observationMs: 0, + totalMs: 12, + }); + }); + + it('measures each phase', () => { + useFakeClock(0); + const timer = new RequestTimer(0); + now = 5; + timer.markEnqueued(); + now = 25; + timer.markTaskStart(); + now = 125; + timer.markToolEnd(); + now = 130; + timer.markObservationStart(); + now = 180; + timer.markObservationEnd(); + now = 190; + + expect(timer.snapshot()).toStrictEqual({ + queueMs: 20, + toolMs: 100, + observationMs: 50, + totalMs: 190, + }); + }); + + it('measures an unfinished phase up to the snapshot', () => { + useFakeClock(0); + const timer = new RequestTimer(0); + timer.markEnqueued(); + timer.markTaskStart(); + now = 40; + + expect(timer.snapshot().toolMs).toBe(40); + }); + + it('never reports totalMs below the sum of the rounded phases', () => { + useFakeClock(0); + const timer = new RequestTimer(0); + timer.markEnqueued(); + now = 0.5; + timer.markTaskStart(); + now = 1; + timer.markToolEnd(); + timer.markObservationStart(); + now = 1.5; + timer.markObservationEnd(); + + // Each phase rounds up to 1ms; the 1.5ms total would round to 2. + expect(timer.snapshot()).toStrictEqual({ + queueMs: 1, + toolMs: 1, + observationMs: 1, + totalMs: 3, + }); + }); + + it('defaults the request start to now', () => { + useFakeClock(500); + const timer = new RequestTimer(); + now = 503; + + expect(timer.meta()).toStrictEqual({ + timing: { queueMs: 0, toolMs: 0, observationMs: 0, totalMs: 3 }, + }); + }); +}); + +describe('withMeta', () => { + const meta = { + timing: { queueMs: 1, toolMs: 2, observationMs: 3, totalMs: 7 }, + }; + + it('appends meta as the last key of an object body', () => { + const body = withMeta({ ok: true, result: { a: 1 } }, meta); + + expect(body).toStrictEqual({ ok: true, result: { a: 1 }, meta }); + expect(Object.keys(body as object)).toStrictEqual(['ok', 'result', 'meta']); + }); + + it.each([['text'], [null], [42], [[1, 2]]])( + 'returns non-object body %j unchanged', + (body) => { + expect(withMeta(body, meta)).toBe(body); + }, + ); +}); diff --git a/src/server/response-timing.ts b/src/server/response-timing.ts new file mode 100644 index 0000000..c4902c5 --- /dev/null +++ b/src/server/response-timing.ts @@ -0,0 +1,130 @@ +import type express from 'express'; + +import type { ToolResponseMeta, ToolResponseTiming } from '../types/http.js'; + +/** + * Records the phases of one tool request with a monotonic clock and turns + * them into a {@link ToolResponseTiming}. + * + * Phases that never started report 0. A phase that started but did not end + * (for example a tool that was still running when the queue timed out) is + * measured up to the moment of the snapshot. + */ +export class RequestTimer { + readonly #requestStart: number; + + #enqueuedAt: number | undefined; + + #taskStartedAt: number | undefined; + + #toolEndedAt: number | undefined; + + #observationStartedAt: number | undefined; + + #observationEndedAt: number | undefined; + + /** + * @param requestStart - `performance.now()` value when the request arrived. + * Defaults to now. + */ + constructor(requestStart: number = performance.now()) { + this.#requestStart = requestStart; + } + + /** Marks the moment the task was handed to the request queue. */ + markEnqueued(): void { + this.#enqueuedAt = performance.now(); + } + + /** Marks the moment the queued task started (the tool is about to run). */ + markTaskStart(): void { + this.#taskStartedAt = performance.now(); + } + + /** Marks the end of the tool function call. */ + markToolEnd(): void { + this.#toolEndedAt = performance.now(); + } + + /** Marks the start of observation collection. */ + markObservationStart(): void { + this.#observationStartedAt = performance.now(); + } + + /** Marks the end of observation collection. */ + markObservationEnd(): void { + this.#observationEndedAt = performance.now(); + } + + /** + * Returns the timing so far, in whole milliseconds. + * + * @returns The timing; `totalMs` is never less than the sum of the phases. + */ + snapshot(): ToolResponseTiming { + const now = performance.now(); + const span = ( + start: number | undefined, + end: number | undefined, + ): number => + start === undefined ? 0 : Math.max(0, Math.round((end ?? now) - start)); + + const queueMs = span(this.#enqueuedAt, this.#taskStartedAt); + const toolMs = span(this.#taskStartedAt, this.#toolEndedAt); + const observationMs = span( + this.#observationStartedAt, + this.#observationEndedAt, + ); + const totalMs = Math.max( + span(this.#requestStart, undefined), + queueMs + toolMs + observationMs, + ); + return { queueMs, toolMs, observationMs, totalMs }; + } + + /** + * Returns the `meta` object for a response body. + * + * @returns The response metadata with the current timing. + */ + meta(): ToolResponseMeta { + return { timing: this.snapshot() }; + } +} + +/** + * Adds `meta` to a response body. Bodies that are not plain objects (strings, + * arrays, null) are returned unchanged. + * + * @param body - The response body. + * @param meta - The metadata to attach. + * @returns The body with `meta` as its last key. + */ +export function withMeta(body: unknown, meta: ToolResponseMeta): unknown { + if (typeof body !== 'object' || body === null || Array.isArray(body)) { + return body; + } + return { ...(body as Record), meta }; +} + +const requestStarts = new WeakMap(); + +/** + * Records when a request arrived. Call it before the body parser runs. + * + * @param res - The Express response for the request. + * @param start - `performance.now()` value when the request arrived. + */ +export function setRequestStart(res: express.Response, start: number): void { + requestStarts.set(res, start); +} + +/** + * Returns when a request arrived, as recorded by {@link setRequestStart}. + * + * @param res - The Express response for the request. + * @returns The recorded start, or now if none was recorded. + */ +export function requestStartOf(res: express.Response): number { + return requestStarts.get(res) ?? performance.now(); +} diff --git a/src/types/http.ts b/src/types/http.ts index 6daf1ed..604f99d 100644 --- a/src/types/http.ts +++ b/src/types/http.ts @@ -44,6 +44,30 @@ export type ToolResponse = | { ok: true; result: T } | { ok: false; error: { code: string; message: string } }; +/** + * Server-side timing of one tool request, in whole milliseconds. + * + * Phases that did not run (for example `toolMs` for a validation error) are 0. + * `totalMs` is always at least `queueMs + toolMs + observationMs`. + */ +export type ToolResponseTiming = { + /** Time from enqueue until the queued task started (waiting for earlier requests). */ + queueMs: number; + /** Time spent inside the tool function. */ + toolMs: number; + /** Time spent collecting the post-tool observation (0 when skipped). */ + observationMs: number; + /** Time from request received until the response was sent. */ + totalMs: number; +}; + +/** + * Metadata attached to every `/tool/*`, `/launch` and `/cleanup` response body. + */ +export type ToolResponseMeta = { + timing: ToolResponseTiming; +}; + /** * Standalone tool function signature. * From 226efd8ac2694046c0601ce6b5e1d901efc1d54b Mon Sep 17 00:00:00 2001 From: cryptotavares Date: Tue, 27 Oct 2026 12:07:08 +0000 Subject: [PATCH 2/2] chore: move benchmark to mm-cli-v2 proof tooling --- scripts/bench.mjs | 173 ---------------------------------------------- 1 file changed, 173 deletions(-) delete mode 100644 scripts/bench.mjs diff --git a/scripts/bench.mjs b/scripts/bench.mjs deleted file mode 100644 index 1855ca4..0000000 --- a/scripts/bench.mjs +++ /dev/null @@ -1,173 +0,0 @@ -#!/usr/bin/env node -/* eslint-disable import-x/no-nodejs-modules */ -// Benchmark `mm` commands against a running session (not shipped). -// -// Usage (run from the consumer worktree that owns the session): -// node /scripts/bench.mjs [--runs N] [--mm ""] -- [ ...] -// -// Each is one mm invocation, quoted if it has arguments: -// node bench.mjs --runs 5 -- describe-screen get-state \ -// "cdp Runtime.evaluate '{\"expression\":\"1+1\"}'" -// -// Prints TSV to stdout: median and p95 (nearest rank; with 5 runs p95 is the -// max) of wall clock, response bytes and meta.timing.{queueMs,toolMs, -// observationMs,totalMs}. Wall clock includes the `--mm` launcher start-up -// (about 1 s for `yarn mm`). Runs that exit non-zero, time out (--timeout-ms, -// default 180000) or are killed count in `fail` and are left out of the stats. - -import { Buffer } from 'node:buffer'; -import { spawnSync } from 'node:child_process'; -import process from 'node:process'; - -const USAGE = - 'usage: bench.mjs [--runs N] [--timeout-ms MS] [--mm ""] -- [ ...]'; - -/** - * Parses the command line. - * - * @param {string[]} argv - Arguments after the script name. - * @returns {{ runs: number, timeoutMs: number, mm: string, commands: string[] }} The options. - */ -function parseArgs(argv) { - let runs = 5; - let timeoutMs = 180_000; - let mm = 'yarn mm'; - const sep = argv.indexOf('--'); - const opts = sep === -1 ? argv : argv.slice(0, sep); - const commands = sep === -1 ? [] : argv.slice(sep + 1); - for (let i = 0; i < opts.length; i++) { - const flag = opts[i]; - const value = opts[i + 1]; - if (flag === '--runs' && value) { - runs = Number(value); - i += 1; - } else if (flag === '--timeout-ms' && value) { - timeoutMs = Number(value); - i += 1; - } else if (flag === '--mm' && value) { - mm = value; - i += 1; - } else { - throw new Error(`unknown option ${flag}\n${USAGE}`); - } - } - if (!Number.isInteger(runs) || runs < 1) { - throw new Error(`--runs must be a positive integer\n${USAGE}`); - } - if (!Number.isInteger(timeoutMs) || timeoutMs < 1) { - throw new Error(`--timeout-ms must be a positive integer\n${USAGE}`); - } - if (commands.length === 0) { - throw new Error(USAGE); - } - return { runs, timeoutMs, mm, commands }; -} - -/** - * Returns a quantile (nearest rank) of a list of numbers. - * - * @param {number[]} values - The samples. - * @param {number} fraction - Quantile in [0, 1]. - * @returns {number | string} The quantile, or '-' when there are no samples. - */ -function quantile(values, fraction) { - if (values.length === 0) { - return '-'; - } - const sorted = [...values].sort((a, b) => a - b); - const rank = Math.max(1, Math.ceil(fraction * sorted.length)); - return Math.round(sorted[rank - 1]); -} - -/** - * Runs one mm command once. - * - * @param {string} mm - The mm invocation (for example `yarn mm`). - * @param {string} command - The command and its arguments. - * @param {number} timeoutMs - Kill the run after this many milliseconds. - * @returns {{ ok: boolean, wallMs: number, bytes: number, timing?: Record }} The run result. - */ -function runOnce(mm, command, timeoutMs) { - const start = performance.now(); - const proc = spawnSync(`${mm} ${command}`, { - shell: true, - encoding: 'utf8', - maxBuffer: 64 * 1024 * 1024, - timeout: timeoutMs, - }); - const wallMs = performance.now() - start; - const stdout = proc.stdout ?? ''; - let timing; - try { - timing = JSON.parse(stdout)?.meta?.timing; - } catch { - // string output or not JSON: no timing - } - return { - ok: proc.status === 0 && !proc.error && !proc.signal, - wallMs, - bytes: Buffer.byteLength(stdout), - timing, - }; -} - -const FIELDS = ['queueMs', 'toolMs', 'observationMs', 'totalMs']; - -/** - * Entry point. - */ -function main() { - let options; - try { - options = parseArgs(process.argv.slice(2)); - } catch (error) { - process.stderr.write(`${error.message}\n`); - process.exit(2); - } - const { runs, timeoutMs, mm, commands } = options; - - const header = ['command', 'runs', 'fail', 'wall_p50', 'wall_p95']; - header.push('bytes_p50'); - for (const field of FIELDS) { - header.push(`${field}_p50`, `${field}_p95`); - } - process.stdout.write(`${header.join('\t')}\n`); - - for (const command of commands) { - const results = []; - for (let i = 0; i < runs; i++) { - const result = runOnce(mm, command, timeoutMs); - results.push(result); - process.stderr.write( - `${command} #${i + 1}: ${Math.round(result.wallMs)}ms ${result.ok ? 'ok' : 'FAIL'}\n`, - ); - } - const ok = results.filter((result) => result.ok); - const row = [ - command.replace(/\s+/gu, ' '), - runs, - runs - ok.length, - quantile( - ok.map((result) => result.wallMs), - 0.5, - ), - quantile( - ok.map((result) => result.wallMs), - 0.95, - ), - quantile( - ok.map((result) => result.bytes), - 0.5, - ), - ]; - for (const field of FIELDS) { - const samples = ok - .map((result) => result.timing?.[field]) - .filter((value) => typeof value === 'number'); - row.push(quantile(samples, 0.5), quantile(samples, 0.95)); - } - process.stdout.write(`${row.join('\t')}\n`); - } -} - -main();