feat: add CLI debug timing helper

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");
+  });
+});

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<string, TimingDetailValue>;
+type TimingMode = "off" | "pretty" | "json";
+
+type TimingPayload = {
+  command: string;
+  phase: string;
+  elapsedMs: number;
+  deltaMs: number;
+} & Record<string, string | number | boolean | null>;
+
+type TimingWriter = (line: string) => void;
+
+export type CliDebugTiming = {
+  enabled: boolean;
+  mark: (phase: string, details?: TimingDetails) => void;
+  time: <T>(
+    phase: string,
+    fn: () => T,
+    details?: TimingDetails | ((result: T) => TimingDetails),
+  ) => T;
+  timeAsync: <T>(
+    phase: string,
+    fn: () => Promise<T>,
+    details?: TimingDetails | ((result: T) => TimingDetails),
+  ) => Promise<T>;
+};
+
+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<T>(
+  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<T>(
+      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<T>(
+      phase: string,
+      fn: () => Promise<T>,
+      details?: TimingDetails | ((result: T) => TimingDetails),
+    ): Promise<T> {
+      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";
+}