diff --git a/src/cli/debug-timing.test.ts b/src/cli/debug-timing.test.ts deleted file mode 100644 index a7b65108a6c..00000000000 --- a/src/cli/debug-timing.test.ts +++ /dev/null @@ -1,99 +0,0 @@ -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 deleted file mode 100644 index d5970b5ccf7..00000000000 --- a/src/cli/debug-timing.ts +++ /dev/null @@ -1,228 +0,0 @@ -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; -type NonPromise = T extends PromiseLike ? never : T; - -type CliDebugTiming = { - enabled: boolean; - mark: (phase: string, details?: TimingDetails) => void; - time: ( - phase: string, - fn: () => NonPromise, - details?: TimingDetails | ((result: NonPromise) => TimingDetails), - ) => NonPromise; - 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 formatPrettyLabel(value: string): string { - return JSON.stringify(value); -} - -function isPromiseLike(value: unknown): value is PromiseLike { - return ( - typeof value === "object" && - value !== null && - "then" in value && - typeof (value as { then?: unknown }).then === "function" - ); -} - -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)} ${formatPrettyLabel(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: ${formatPrettyLabel(params.command)}`); - wrotePrettyHeader = true; - } - writer(formatPrettyTimingLine(payload)); - }; - - return { - enabled, - mark, - time( - phase: string, - fn: () => NonPromise, - details?: TimingDetails | ((result: NonPromise) => TimingDetails), - ): NonPromise { - const started = enabled ? performance.now() : 0; - try { - const result = fn(); - if (isPromiseLike(result)) { - void Promise.resolve(result).catch(() => undefined); - throw new Error("CLI debug timing time() received a Promise; use timeAsync() instead."); - } - 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"; -}