diff --git a/docs/help/debugging.md b/docs/help/debugging.md index fb0162a95d8..38e842aea0a 100644 --- a/docs/help/debugging.md +++ b/docs/help/debugging.md @@ -86,6 +86,7 @@ Guidelines: - Add only a few spans around suspected slow sections. - Prefer broad phases such as `registry`, `auth_store`, or `rows` over helper names. +- Use `time()` for synchronous work and `timeAsync()` for promises. - Keep stdout clean. The helper writes to stderr, so command JSON output stays parseable. - Remove temporary imports and spans before opening the final fix PR. @@ -171,12 +172,15 @@ Each stderr line is one JSON object: Before opening the final PR: ```bash -rg "createCliDebugTiming|debug:" src +rg 'createCliDebugTiming|debug:[a-z0-9_-]+:' src/commands src/cli \ + --glob '!src/cli/debug-timing.*' \ + --glob '!*.test.ts' ``` -The command should return no production call sites unless the PR is explicitly -adding a permanent diagnostics surface. For normal performance fixes, keep only -the behavior change, tests, and a short note with the timing evidence. +The command should return no temporary instrumentation call sites unless the PR +is explicitly adding a permanent diagnostics surface. For normal performance +fixes, keep only the behavior change, tests, and a short note with the timing +evidence. For deeper CPU hotspots, use Node profiling (`--cpu-prof`) or an external profiler instead of adding more timing wrappers. diff --git a/src/cli/debug-timing.test.ts b/src/cli/debug-timing.test.ts index 6a97c6c402b..a7b65108a6c 100644 --- a/src/cli/debug-timing.test.ts +++ b/src/cli/debug-timing.test.ts @@ -41,9 +41,9 @@ describe("cli debug timing", () => { 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/), + '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/), ]); }); diff --git a/src/cli/debug-timing.ts b/src/cli/debug-timing.ts index a6017420a7b..3bab56920f6 100644 --- a/src/cli/debug-timing.ts +++ b/src/cli/debug-timing.ts @@ -14,15 +14,16 @@ type TimingPayload = { } & Record; type TimingWriter = (line: string) => void; +type NonPromise = T extends PromiseLike ? never : T; export type CliDebugTiming = { enabled: boolean; mark: (phase: string, details?: TimingDetails) => void; time: ( phase: string, - fn: () => T, - details?: TimingDetails | ((result: T) => TimingDetails), - ) => T; + fn: () => NonPromise, + details?: TimingDetails | ((result: NonPromise) => TimingDetails), + ) => NonPromise; timeAsync: ( phase: string, fn: () => Promise, @@ -94,6 +95,19 @@ function formatPrettyDetailValue(value: string | number | boolean | null): strin 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( @@ -108,7 +122,7 @@ function formatPrettyTimingLine(payload: TimingPayload): string { 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}`; + return `${formatDuration(payload.elapsedMs).padStart(8)} ${`+${formatDuration(payload.deltaMs)}`.padStart(8)} ${formatPrettyLabel(payload.phase)}${duration}${suffix}`; } export function createCliDebugTiming(params: { @@ -143,7 +157,7 @@ export function createCliDebugTiming(params: { return; } if (!wrotePrettyHeader) { - writer(`OpenClaw CLI debug timing: ${params.command}`); + writer(`OpenClaw CLI debug timing: ${formatPrettyLabel(params.command)}`); wrotePrettyHeader = true; } writer(formatPrettyTimingLine(payload)); @@ -154,12 +168,16 @@ export function createCliDebugTiming(params: { mark, time( phase: string, - fn: () => T, - details?: TimingDetails | ((result: T) => TimingDetails), - ): T { + 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),