diff --git a/src/cli/debug-timing.test.ts b/src/cli/debug-timing.test.ts new file mode 100644 index 00000000000..6a97c6c402b --- /dev/null +++ b/src/cli/debug-timing.test.ts @@ -0,0 +1,99 @@ +import { describe, expect, it, vi } from "vitest"; +import { createCliDebugTiming, formatCliDebugTimingCommand } from "./debug-timing.js"; + +function parseJsonTimingLine(line: string) { + return JSON.parse(line) as { + command: string; + phase: string; + elapsedMs: number; + deltaMs: number; + durationMs?: number; + detail?: string; + error?: boolean; + }; +} + +describe("cli debug timing", () => { + it("does not emit timing lines unless OPENCLAW_DEBUG_TIMING enables a mode", () => { + const writer = vi.fn(); + const timing = createCliDebugTiming({ + command: "models list", + env: {}, + writer, + }); + + timing.mark("start"); + timing.time("sync", () => 1); + + expect(timing.enabled).toBe(false); + expect(writer).not.toHaveBeenCalled(); + }); + + it("emits readable timing lines with OPENCLAW_DEBUG_TIMING=1", () => { + const writer = vi.fn(); + const timing = createCliDebugTiming({ + command: "models list", + env: { OPENCLAW_DEBUG_TIMING: "1" }, + writer, + }); + + timing.mark("start", { detail: "ready" }); + expect(timing.time("sync", () => 1)).toBe(1); + + expect(writer.mock.calls.map(([line]) => String(line))).toEqual([ + "OpenClaw CLI debug timing: models list", + expect.stringMatching(/\s+\d+ms\s+\+\d+ms start detail="ready"/), + expect.stringMatching(/\s+\d+ms\s+\+\d+ms sync duration=\d+ms/), + ]); + }); + + it("emits parseable timing JSON lines with OPENCLAW_DEBUG_TIMING=json", async () => { + const writer = vi.fn(); + const timing = createCliDebugTiming({ + command: "models list", + env: { OPENCLAW_DEBUG_TIMING: "json" }, + writer, + }); + + timing.mark("start", { detail: "ready" }); + expect(timing.time("sync", () => 1)).toBe(1); + await expect(timing.timeAsync("async", async () => "ok")).resolves.toBe("ok"); + await expect( + timing.timeAsync("reject", async () => { + throw new Error("nope"); + }), + ).rejects.toThrow("nope"); + + const payloads = writer.mock.calls.map(([line]) => parseJsonTimingLine(String(line))); + expect(payloads).toEqual([ + expect.objectContaining({ + command: "models list", + phase: "start", + detail: "ready", + elapsedMs: expect.any(Number), + deltaMs: expect.any(Number), + }), + expect.objectContaining({ + command: "models list", + phase: "sync", + durationMs: expect.any(Number), + }), + expect.objectContaining({ + command: "models list", + phase: "async", + durationMs: expect.any(Number), + }), + expect.objectContaining({ + command: "models list", + phase: "reject", + durationMs: expect.any(Number), + error: true, + }), + ]); + }); + + it("formats empty command paths as root", () => { + expect(formatCliDebugTimingCommand([])).toBe("root"); + expect(formatCliDebugTimingCommand(["models", "list"])).toBe("models list"); + }); +}); diff --git a/src/cli/debug-timing.ts b/src/cli/debug-timing.ts new file mode 100644 index 00000000000..a6017420a7b --- /dev/null +++ b/src/cli/debug-timing.ts @@ -0,0 +1,210 @@ +import { performance } from "node:perf_hooks"; + +const CLI_DEBUG_TIMING_ENV = "OPENCLAW_DEBUG_TIMING"; + +type TimingDetailValue = string | number | boolean | null | undefined; +type TimingDetails = Record; +type TimingMode = "off" | "pretty" | "json"; + +type TimingPayload = { + command: string; + phase: string; + elapsedMs: number; + deltaMs: number; +} & Record; + +type TimingWriter = (line: string) => void; + +export type CliDebugTiming = { + enabled: boolean; + mark: (phase: string, details?: TimingDetails) => void; + time: ( + phase: string, + fn: () => T, + details?: TimingDetails | ((result: T) => TimingDetails), + ) => T; + timeAsync: ( + phase: string, + fn: () => Promise, + details?: TimingDetails | ((result: T) => TimingDetails), + ) => Promise; +}; + +function resolveCliDebugTimingMode(env: NodeJS.ProcessEnv = process.env): TimingMode { + const raw = env[CLI_DEBUG_TIMING_ENV]?.trim().toLowerCase(); + if (raw === "1") { + return "pretty"; + } + if (raw === "json") { + return "json"; + } + return "off"; +} + +function normalizeDetailValue(value: TimingDetailValue): string | number | boolean | null { + if (typeof value === "number") { + return Number.isFinite(value) ? value : null; + } + return value ?? null; +} + +function appendDetails(payload: TimingPayload, details?: TimingDetails): TimingPayload { + if (!details) { + return payload; + } + for (const [key, value] of Object.entries(details)) { + if (value === undefined) { + continue; + } + payload[key] = normalizeDetailValue(value); + } + return payload; +} + +function defaultTimingWriter(line: string): void { + try { + process.stderr.write(`${line}\n`); + } catch (error) { + const code = (error as NodeJS.ErrnoException)?.code; + if (code === "EPIPE" || code === "EIO") { + return; + } + throw error; + } +} + +function resolveDetails( + details: TimingDetails | ((result: T) => TimingDetails) | undefined, + result: T, +): TimingDetails | undefined { + return typeof details === "function" ? details(result) : details; +} + +function formatDuration(ms: number): string { + if (ms >= 1000) { + return `${(ms / 1000).toFixed(1)}s`; + } + return `${ms}ms`; +} + +function formatPrettyDetailValue(value: string | number | boolean | null): string { + if (typeof value === "string") { + return JSON.stringify(value); + } + return String(value); +} + +function formatPrettyTimingLine(payload: TimingPayload): string { + const details = Object.entries(payload) + .filter( + ([key]) => + key !== "command" && + key !== "phase" && + key !== "elapsedMs" && + key !== "deltaMs" && + key !== "durationMs", + ) + .map(([key, value]) => `${key}=${formatPrettyDetailValue(value)}`); + const duration = + typeof payload.durationMs === "number" ? ` duration=${formatDuration(payload.durationMs)}` : ""; + const suffix = details.length > 0 ? ` ${details.join(" ")}` : ""; + return `${formatDuration(payload.elapsedMs).padStart(8)} ${`+${formatDuration(payload.deltaMs)}`.padStart(8)} ${payload.phase}${duration}${suffix}`; +} + +export function createCliDebugTiming(params: { + command: string; + env?: NodeJS.ProcessEnv; + writer?: TimingWriter; +}): CliDebugTiming { + const mode = resolveCliDebugTimingMode(params.env); + const enabled = mode !== "off"; + const writer = params.writer ?? defaultTimingWriter; + const startedAt = performance.now(); + let lastAt = startedAt; + let wrotePrettyHeader = false; + + const mark = (phase: string, details?: TimingDetails) => { + if (!enabled) { + return; + } + const now = performance.now(); + const payload = appendDetails( + { + command: params.command, + phase, + elapsedMs: Math.round(now - startedAt), + deltaMs: Math.round(now - lastAt), + }, + details, + ); + lastAt = now; + if (mode === "json") { + writer(JSON.stringify(payload)); + return; + } + if (!wrotePrettyHeader) { + writer(`OpenClaw CLI debug timing: ${params.command}`); + wrotePrettyHeader = true; + } + writer(formatPrettyTimingLine(payload)); + }; + + return { + enabled, + mark, + time( + phase: string, + fn: () => T, + details?: TimingDetails | ((result: T) => TimingDetails), + ): T { + const started = enabled ? performance.now() : 0; + try { + const result = fn(); + if (enabled) { + mark(phase, { + durationMs: Math.round(performance.now() - started), + ...resolveDetails(details, result), + }); + } + return result; + } catch (error) { + if (enabled) { + mark(phase, { + durationMs: Math.round(performance.now() - started), + error: true, + }); + } + throw error; + } + }, + async timeAsync( + phase: string, + fn: () => Promise, + details?: TimingDetails | ((result: T) => TimingDetails), + ): Promise { + const started = enabled ? performance.now() : 0; + try { + const result = await fn(); + if (enabled) { + mark(phase, { + durationMs: Math.round(performance.now() - started), + ...resolveDetails(details, result), + }); + } + return result; + } catch (error) { + if (enabled) { + mark(phase, { + durationMs: Math.round(performance.now() - started), + error: true, + }); + } + throw error; + } + }, + }; +} + +export function formatCliDebugTimingCommand(commandPath: readonly string[]): string { + return commandPath.length > 0 ? commandPath.join(" ") : "root"; +}