From 106f0f08215e731e523a63016ac55a196302c3a1 Mon Sep 17 00:00:00 2001 From: Shakker Date: Thu, 23 Apr 2026 04:44:50 +0100 Subject: [PATCH] docs: document temporary CLI debug timing --- docs/help/debugging.md | 135 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 135 insertions(+) diff --git a/docs/help/debugging.md b/docs/help/debugging.md index 88de00e6ca2..fb0162a95d8 100644 --- a/docs/help/debugging.md +++ b/docs/help/debugging.md @@ -46,6 +46,141 @@ Use `/trace` for plugin diagnostics such as Active Memory debug summaries. Keep using `/verbose` for normal verbose status/tool output, and keep using `/debug` for runtime-only config overrides. +## Temporary CLI debug timing + +OpenClaw keeps `src/cli/debug-timing.ts` as a small helper for local +investigation. It is intentionally not wired into CLI startup, command routing, +or any command by default. Use it only while debugging a slow command, then +remove the import and spans before landing the behavior change. + +Use this when a command is slow and you need a quick phase breakdown before +deciding whether to use a CPU profiler or fix a specific subsystem. + +### Add temporary spans + +Add the helper near the code you are investigating. For example, while debugging +`openclaw models list`, a temporary patch in +`src/commands/models/list.list-command.ts` might look like this: + +```ts +// Temporary debugging only. Remove before landing. +import { createCliDebugTiming } from "../../cli/debug-timing.js"; + +const timing = createCliDebugTiming({ command: "models list" }); + +const authStore = timing.time("debug:models:list:auth_store", () => ensureAuthProfileStore()); + +const loaded = await timing.timeAsync( + "debug:models:list:registry", + () => loadListModelRegistry(cfg, { sourceConfig }), + (result) => ({ + models: result.models.length, + discoveredKeys: result.discoveredKeys.size, + }), +); +``` + +Guidelines: + +- Prefix temporary phase names with `debug:`. +- Add only a few spans around suspected slow sections. +- Prefer broad phases such as `registry`, `auth_store`, or `rows` over helper + names. +- 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. +- Include the timing output or a short summary in the issue or PR that explains + the optimization. + +### Run with readable output + +Readable mode is best for live debugging: + +```bash +OPENCLAW_DEBUG_TIMING=1 pnpm openclaw models list --all --provider moonshot +``` + +Example output from a temporary `models list` investigation: + +```text +OpenClaw CLI debug timing: models list + 0ms +0ms start all=true json=false local=false plain=false provider="moonshot" + 2ms +2ms debug:models:list:import_runtime duration=2ms + 17ms +14ms debug:models:list:load_config duration=14ms sourceConfig=true + 20.3s +20.3s debug:models:list:auth_store duration=20.3s + 20.3s +0ms debug:models:list:resolve_agent_dir duration=0ms agentDir=true + 20.3s +0ms debug:models:list:resolve_provider_filter duration=0ms + 25.3s +5.0s debug:models:list:ensure_models_json duration=5.0s + 31.2s +5.9s debug:models:list:load_model_registry duration=5.9s models=869 availableKeys=38 discoveredKeys=868 availabilityError=false + 31.2s +0ms debug:models:list:resolve_configured_entries duration=0ms entries=1 + 31.2s +0ms debug:models:list:build_configured_lookup duration=0ms entries=1 + 33.6s +2.4s debug:models:list:read_registry_models duration=2.4s models=871 + 35.2s +1.5s debug:models:list:append_discovered_rows duration=1.5s seenKeys=0 rows=0 + 36.9s +1.7s debug:models:list:append_catalog_supplement_rows duration=1.7s seenKeys=5 rows=5 + +Model Input Ctx Local Auth Tags +moonshot/kimi-k2-thinking text 256k no no +moonshot/kimi-k2-thinking-turbo text 256k no no +moonshot/kimi-k2-turbo text 250k no no +moonshot/kimi-k2.5 text+image 256k no no +moonshot/kimi-k2.6 text+image 256k no no + + 36.9s +0ms debug:models:list:print_model_table duration=0ms rows=5 + 36.9s +0ms complete rows=5 +``` + +Findings from this output: + +| Phase | Time | What it means | +| ---------------------------------------- | ---------: | ------------------------------------------------------------------------------------------------------- | +| `debug:models:list:auth_store` | 20.3s | The auth-profile store load is the largest cost and should be investigated first. | +| `debug:models:list:ensure_models_json` | 5.0s | Syncing `models.json` is expensive enough to inspect for caching or skip conditions. | +| `debug:models:list:load_model_registry` | 5.9s | Registry construction and provider availability work are also meaningful costs. | +| `debug:models:list:read_registry_models` | 2.4s | Reading all registry models is not free and may matter for `--all`. | +| row append phases | 3.2s total | Building five displayed rows still takes several seconds, so the filtering path deserves a closer look. | +| `debug:models:list:print_model_table` | 0ms | Rendering is not the bottleneck. | + +Those findings are enough to guide the next patch without keeping timing code in +production paths. + +### Run with JSON output + +Use JSON mode when you want to save or compare timing data: + +```bash +OPENCLAW_DEBUG_TIMING=json pnpm openclaw models list --all --provider moonshot \ + 2> .artifacts/models-list-timing.jsonl +``` + +Each stderr line is one JSON object: + +```json +{ + "command": "models list", + "phase": "debug:models:list:registry", + "elapsedMs": 31200, + "deltaMs": 5900, + "durationMs": 5900, + "models": 869, + "discoveredKeys": 868 +} +``` + +### Clean up before landing + +Before opening the final PR: + +```bash +rg "createCliDebugTiming|debug:" src +``` + +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. + +For deeper CPU hotspots, use Node profiling (`--cpu-prof`) or an external +profiler instead of adding more timing wrappers. + ## Gateway watch mode For fast iteration, run the gateway under the file watcher: