docs: document temporary CLI debug timing

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: