fix: harden CLI debug timing helper

This commit is contained in:
Shakker
2026-04-23 05:09:55 +01:00
committed by Shakker
parent 106f0f0821
commit d60eb9a4a4
3 changed files with 37 additions and 15 deletions

View File

@@ -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.

View File

@@ -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/),
]);
});

View File

@@ -14,15 +14,16 @@ type TimingPayload = {
} & Record<string, string | number | boolean | null>;
type TimingWriter = (line: string) => void;
type NonPromise<T> = T extends PromiseLike<unknown> ? never : T;
export type CliDebugTiming = {
enabled: boolean;
mark: (phase: string, details?: TimingDetails) => void;
time: <T>(
phase: string,
fn: () => T,
details?: TimingDetails | ((result: T) => TimingDetails),
) => T;
fn: () => NonPromise<T>,
details?: TimingDetails | ((result: NonPromise<T>) => TimingDetails),
) => NonPromise<T>;
timeAsync: <T>(
phase: string,
fn: () => Promise<T>,
@@ -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<unknown> {
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<T>(
phase: string,
fn: () => T,
details?: TimingDetails | ((result: T) => TimingDetails),
): T {
fn: () => NonPromise<T>,
details?: TimingDetails | ((result: NonPromise<T>) => TimingDetails),
): NonPromise<T> {
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),