refactor(perf): canonicalize the benchmark / wt-perf system

.claude/skills/running-tend/SKILL.md

@@ -161,9 +161,9 @@ When the report is about a slow `wt` command, read its **Performance profile**
 section first. It renders the same breakdown as `wt config state logs profile`
 (subprocess time by command type, slowest calls, repeated `(command, context)`
 pairs) directly from the bundled `trace.log`, so you can spot redundant git
-calls and slow commands without parsing the raw trace by hand. The deeper
-per-render cache analysis is a separate tool — see **Weekly Maintenance:
-Statusline Cache-Check**.
+calls and slow commands without parsing the raw trace by hand. The same
+report run against a statusline capture is the weekly per-render cache
+check — see **Weekly Maintenance: Statusline Cache-Check**.
 
 Reach for narrower asks only when the diagnostic is overkill:
 
@@ -288,9 +288,9 @@ Discovery shortcut: a recent green CI run on `main` flags cargo-install drift di
 ## Weekly Maintenance: Statusline Cache-Check
 
 Detect new in-process cache-miss duplicates introduced by recent changes by
-running `wt-perf cache-check` against a real `wt list statusline --claude-code`
-trace. The render runs on every Claude Code prompt redraw, so duplicate git
-subprocesses there compound into measurable fseventsd / IPC load.
+profiling a real `wt list statusline --claude-code` trace. The render runs on
+every Claude Code prompt redraw, so duplicate git subprocesses there compound
+into measurable fseventsd / IPC load.
 
 ```bash
 # Run from any worktree of this repo
@@ -300,12 +300,12 @@ cat > /tmp/statusline-input.json <<'EOF'
 EOF
 sed -i '' "s|REPLACE_WITH_CWD|$PWD|" /tmp/statusline-input.json
 
-RUST_LOG=debug cargo run --release -- list statusline --claude-code \
-  < /tmp/statusline-input.json 2>&1 \
-  | cargo run -p wt-perf -- cache-check
+cargo run --release -- -vv list statusline --claude-code \
+  < /tmp/statusline-input.json > /dev/null
+cargo run --release -- config state logs profile --format=json | jq .cache
 ```
 
-The report flags commands invoked more than once with the same context.
+The `.cache` report flags commands invoked more than once with the same context.
 Triage each duplicate:
 
 - **Legitimate** (different cwd, different ref form that can't be normalized,

.config/nextest.toml

@@ -23,45 +23,46 @@ success-output = "never"
 [profile.default.junit]
 path = "junit.xml"
 
-# Build the helper binaries (`mock-stub`, `wt-perf`) before any test runs.
+# Build the `mock-stub` helper binary before any test runs.
 #
-# These live in separate workspace packages so cargo-dist doesn't ship them
+# It lives in a separate workspace package so cargo-dist doesn't ship it
 # (see tests/helpers/mock-stub/Cargo.toml for the rationale). The
-# `default-members` setting builds them under unfiltered `cargo nextest run`,
+# `default-members` setting builds it under unfiltered `cargo nextest run`,
 # but a target filter like `--test integration` overrides default-members and
-# the helpers are skipped — so tests that spawn them fail.
+# the helper is skipped — so tests that spawn it fail. (wt-perf, the other
+# helper package, needs no such treatment: its CLI tests live in-package, so
+# cargo builds its binary whenever its tests run.)
 #
 # Under `cargo llvm-cov nextest`, nextest doesn't propagate the outer
 # --target-dir as a CARGO_TARGET_DIR env var, so a plain `cargo build` would
 # write to target/ rather than target/llvm-cov-target/ and the test binary
-# would still find no helpers. Derive the right target-dir from
+# would still find no helper. Derive the right target-dir from
 # LLVM_PROFILE_FILE (cargo-llvm-cov sets it to a path inside its target dir)
 # and pass it through with --target-dir. Worktrunk already requires bash for
 # shell-integration tests on every platform, so bash here is fine.
 #
 # TODO: collapse this whole layer once cargo-dist supports per-binary
-# exclusion. The chain — separate `tests/helpers/{mock-stub,wt-perf}`
-# packages, the dummy `tests/builds.rs` trick that makes `default-members`
-# build them, this setup-script, and `workspace_bin()` in src/testing/mod.rs
-# — exists only because cargo-dist (≤ 0.30.x at time of writing) ships every
-# `[[bin]]` in the main crate and offers no per-binary opt-out. PR #127
-# (commit d21925692) documented the failure modes: `required-features` on
-# `[[bin]]` still trips cargo-dist's "bin not found", and
-# `[package.metadata.dist] dist = false` excludes the entire package, not
-# individual binaries. When cargo-dist gains per-binary exclusion (or we
-# move off cargo-dist), pull mock-stub and wt-perf back into the worktrunk
-# crate as `[[bin]]` targets, use `CARGO_BIN_EXE_<name>`, and delete this
-# script along with `workspace_bin()` and the helper packages.
+# exclusion. The chain — the separate `tests/helpers/mock-stub` package, the
+# dummy `tests/builds.rs` trick that makes `default-members` build it, this
+# setup-script, and `workspace_bin()` in src/testing/mod.rs — exists only
+# because cargo-dist (≤ 0.30.x at time of writing) ships every `[[bin]]` in
+# the main crate and offers no per-binary opt-out. PR #127 (commit d21925692)
+# documented the failure modes: `required-features` on `[[bin]]` still trips
+# cargo-dist's "bin not found", and `[package.metadata.dist] dist = false`
+# excludes the entire package, not individual binaries. When cargo-dist gains
+# per-binary exclusion (or we move off cargo-dist), pull mock-stub back into
+# the worktrunk crate as a `[[bin]]` target, use `CARGO_BIN_EXE_<name>`, and
+# delete this script along with `workspace_bin()` and the helper package.
 [scripts.setup.build-bins]
 command = [
     "bash",
     "-c",
-    'if [ -n "${LLVM_PROFILE_FILE:-}" ]; then cargo build --bin mock-stub --bin wt-perf --target-dir "$(dirname "$LLVM_PROFILE_FILE")"; else cargo build --bin mock-stub --bin wt-perf; fi',
+    'if [ -n "${LLVM_PROFILE_FILE:-}" ]; then cargo build --bin mock-stub --target-dir "$(dirname "$LLVM_PROFILE_FILE")"; else cargo build --bin mock-stub; fi',
 ]
 
 [[profile.default.scripts]]
-# Only the `integration` test binary calls `workspace_bin()` (via MockConfig
-# and analyze_trace.rs), so don't pay the helper-build cost on `--lib`,
-# `--bin wt`, doctest, or bench runs.
+# Only the `integration` test binary calls `workspace_bin()` (via MockConfig),
+# so don't pay the helper-build cost on `--lib`, `--bin wt`, doctest, or
+# bench runs.
 filter = "binary(integration)"
 setup = "build-bins"

CHANGELOG.md

@@ -4,6 +4,8 @@
 
 ### Improved
 
+- **`wt config state logs profile` groups subprocess time by worktree**: The report gained a BY CONTEXT table (and a `by_context` array in `--format=json`) — subprocess time per context, typically the worktree name — so a slow parallel phase can be attributed to the worktree causing it without exporting the trace to an external tool. ([#3403](https://github.com/max-sixty/worktrunk/pull/3403))
+
 - **`-vv` diagnostics surface pager and terminal environment**: The diagnostic report (`.git/wt/logs/diagnostic.md`, written on every `-vv` run) gained an "Environment variables" section listing a curated, non-secret allowlist of the pager / terminal / locale knobs (`PAGER`, `GIT_PAGER`, `TERM`, `COLUMNS`, `NO_COLOR`, `LANG`, …) plus git's resolved `core.pager`. These are the inputs that most often explain a rendering bug — like a pager interaction suspending `wt config show` ([#3322](https://github.com/max-sixty/worktrunk/issues/3322)) — and they were previously invisible in the report. The list is a strict allowlist, never a blanket `env` dump, so no credential-bearing variable can leak into an uploaded report.
 
 ### Fixed

Cargo.toml

@@ -1,6 +1,8 @@
 [workspace]
 members = ["tests/helpers/wt-perf", "tests/helpers/mock-stub"]
-# Include mock-stub and wt-perf so `cargo test` builds their binaries
+# Include the helper packages so a workspace `cargo test` builds their
+# binaries: mock-stub via its dummy tests/builds.rs, wt-perf via its real
+# in-package CLI tests.
 default-members = [".", "tests/helpers/mock-stub", "tests/helpers/wt-perf"]
 
 # cargo-affected input→test rules. cargo-affected selects tests by Rust-line
@@ -335,10 +337,6 @@ harness = false
 name = "list"
 harness = false
 
-[[bench]]
-name = "cow_copy"
-harness = false
-
 [[bench]]
 name = "time_to_first_output"
 harness = false

benches/CLAUDE.md

@@ -51,7 +51,7 @@ cargo bench --bench list -- --exact full/cold   # One exact ID
 
 To skip the slow real-repo and divergent groups, target the synthetic groups directly: `cargo bench --bench list skeleton`, `cargo bench --bench list worktree_scaling`, or `cargo bench --bench list full`. Run them sequentially if you want more than one.
 
-The `full` group is the place to start when `wt list` regresses on a real mix of worktrees and branches: the cold/warm split says whether the cost is the persistent-cache fill (cold) or the per-process re-fork (warm). A `full` wall time can't be split by side (the git subprocesses overlap on the rayon pool), so to localize a regression, trace one invocation and bucket subprocess time per worktree (query #3 below); `worktree_scaling` and `divergent_branches` track the worktree side and branch side respectively at criterion cadence.
+The `full` group is the place to start when `wt list` regresses on a real mix of worktrees and branches: the cold/warm split says whether the cost is the persistent-cache fill (cold) or the per-process re-fork (warm). A `full` wall time can't be split by side (the git subprocesses overlap on the rayon pool), so to localize a regression, trace one invocation and read the profile's BY CONTEXT table ("Analyzing a trace" below); `worktree_scaling` and `divergent_branches` track the worktree side and branch side respectively at criterion cadence.
 
 ## WORKTRUNK_FIRST_OUTPUT
 
@@ -89,21 +89,11 @@ so bench iterations read from prior iterations unless invalidated.
 
 **Rule:** if a benchmark runs a `wt` subcommand that populates these caches, every
 iteration must start cold — otherwise iter 1 measures the real cost and iter 2+ measure
-a cache hit. Invalidate via `criterion::Bencher::iter_batched` with
-`wt_perf::invalidate_caches_auto` as the setup closure (see the cold-cache variants in
-`benches/list.rs` and `benches/remove.rs` for the pattern).
-
-**Pass `BatchSize::PerIteration`, not `BatchSize::SmallInput`.** When the setup
-invalidates a cache that the routine repopulates, the batch size matters:
-`SmallInput` calls `setup()` once per batch up front, then times the routines
-back-to-back inside one timing window, so only iter 1 per batch is actually cold
-— iters 2-N hit a cache that the previous iter just populated. The reported
-"cold" median is a warm-biased average. `PerIteration` runs `setup → time(routine)`
-per iter, so every measured iter is genuinely cold. The setup is far cheaper than
-a `wt` subprocess, so per-iter `Instant::now` overhead doesn't dominate. When the
-fix landed across `list.rs` / `remove.rs` / `time_to_first_output.rs`, cold variance
-tightened (e.g. `first_output/remove` spread 2.4ms → 0.65ms) and the median rose
-to its true cold cost (e.g. `remove_e2e/first_output` 48ms → 86ms).
+a cache hit. Run the iteration through `wt_perf::bench_wt`, the one home of the
+warm/cold strategy (plain `iter` warm; invalidate-per-iteration cold — its doc
+comment carries the `BatchSize::PerIteration` rationale). A cold benchmark whose
+setup is not plain invalidation (e.g. `remove_e2e` recreating the removed
+worktree) uses `iter_batched` with `BatchSize::PerIteration` directly.
 
 `invalidate_caches_auto` clears:
 
@@ -194,7 +184,7 @@ because its ~15 GiB fixture must never build on a hosted CI runner):
 | `prune_e2e/dry_run_warm` | ~90 ms | steady-state re-scan, probes hit sha_cache |
 | `prune_e2e/live` | ~620 ms | cold scan + serial removal of the 8 candidates (~60 ms each, under the scan write lock) |
 | `prune_real_repo/dry_run_warm` | ~0.3–0.8 s | steady-state scan of 72 items (36 worktrees + 36 branches) at 331k-commit scale |
-| `remove_e2e/first_output` | ~86 ms | single-target validation up to first output |
+| `first_output/remove` | ~86 ms | single-target validation up to first output (`benches/time_to_first_output.rs`) |
 
 Cold and live at rust scale are **one-shot timelines, not criterion groups**
 (a cold criterion iteration costs ~1 min in re-hashing statuses alone; a live
@@ -309,7 +299,7 @@ cargo run -p wt-perf -- setup typical-8 --persist
 #   picker-test     - Config for wt switch interactive picker testing
 
 # Invalidate caches for cold run
-cargo run -p wt-perf -- invalidate /tmp/wt-perf-typical-8/main
+cargo run -p wt-perf -- invalidate /tmp/wt-perf-typical-8
 ```
 
 ### Generating traces
@@ -351,103 +341,35 @@ prelude/epilogue not visible to the trace — process spawn, dyld, code
 that runs before `init_logging` registers the trace epoch, and the exit
 path after the last span drops.
 
-### Querying with trace_processor
+### Analyzing a trace
 
-Install [trace_processor](https://perfetto.dev/docs/analysis/trace-processor) for SQL analysis:
+`wt config state logs profile [FILE]` answers the three questions below from a
+captured `trace.jsonl` without leaving the terminal: subprocess time by command
+type and by worktree (BY COMMAND TYPE / BY CONTEXT), the slowest individual
+jobs, the parallelism factor and peak concurrency, same-context duplicate
+commands (CACHE), and the collect milestones (KEY INTERVALS / PHASES).
+`--format=json` emits the same data for scripting.
 
 ```bash
-curl -LO https://get.perfetto.dev/trace_processor && chmod +x trace_processor
+wt -vv list --progressive
+wt config state logs profile             # human report
+wt config state logs profile --format=json | jq .cache
 ```
 
+For visual critical-path inspection — the one thing the aggregate report can't
+show — open the Chrome Trace JSON (`wt-perf timeline --chrome`, or `wt-perf
+trace` on an existing `trace.jsonl`) in <https://ui.perfetto.dev> or
+chrome://tracing.
+
 ### Performance questions
 
 Three questions drive `wt list` performance work:
 
-1. **Where does time go?** Which subprocess types consume the most total time? The category with the highest `total_ms` is where optimization effort has the most impact.
-
-2. **How parallel are we?** Total subprocess time divided by wall time gives a parallelism factor. A factor of 4.0 means 4 commands running concurrently on average. Close to 1.0 means mostly serial execution with headroom to parallelize.
-
-3. **What's on the critical path?** The critical path passes through serial phases (setup, finalization) plus the slowest work item in the parallel phase. We don't have good queries for this yet — the trace format doesn't capture task dependencies, and rayon's work-stealing means thread IDs don't map to worktrees. The queries below are a starting point (phase boundaries from milestones, per-worktree time from args) but don't give a real critical path answer. Visualizing the trace in Perfetto is more useful here.
+1. **Where does time go?** Which subprocess types consume the most total time? The category with the highest total is where optimization effort has the most impact — `by_type` and `slowest` in the profile.
 
-### Queries
+2. **How parallel are we?** Total subprocess time divided by wall time gives a parallelism factor. A factor of 4.0 means 4 commands running concurrently on average. Close to 1.0 means mostly serial execution with headroom to parallelize — `parallelism` and `peak_concurrency` in the profile.
 
-```bash
-# 1. Where does time go? — slowest individual commands
-echo "SELECT name, ts/1e6 as start_ms, dur/1e6 as dur_ms FROM slice WHERE dur > 0 ORDER BY dur DESC LIMIT 10;" | trace_processor trace.json
-
-# 1. Where does time go? — total time by command type
-cat > /tmp/q.sql << 'EOF'
-SELECT
-  CASE WHEN name LIKE '%patch-id%' THEN 'patch_id'
-       WHEN name LIKE '%diff-tree%' THEN 'diff_tree'
-       WHEN name LIKE '%log -p%' THEN 'log_patches'
-       WHEN name LIKE '%merge-tree%' THEN 'merge_tree'
-       WHEN name LIKE '%is-ancestor%' THEN 'is_ancestor'
-       WHEN name LIKE '%diff --name%' THEN 'file_changes'
-       WHEN name LIKE '%diff --numstat%' THEN 'diff_numstat'
-       WHEN name LIKE '%diff --shortstat%' THEN 'diff_shortstat'
-       WHEN name LIKE '%diff --cached%' THEN 'diff_cached'
-       WHEN name LIKE '% diff main...%' THEN 'diff_3dot'
-       WHEN name LIKE '% diff HEAD%' THEN 'diff_wt'
-       WHEN name LIKE '%rev-parse%{tree}%' THEN 'trees_match'
-       WHEN name LIKE '%for-each-ref%' THEN 'for_each_ref'
-       WHEN name LIKE '%worktree list%' THEN 'worktree_list'
-       WHEN name LIKE '%stash create%' THEN 'stash_create'
-       WHEN name LIKE '%sparse-checkout%' THEN 'sparse_checkout'
-       WHEN name LIKE '%rev-list%' THEN 'rev_list'
-       WHEN name LIKE '%claude -p%' THEN 'llm_summary'
-       WHEN name LIKE '%status%' THEN 'status'
-       WHEN name LIKE '%merge-base%' THEN 'merge_base'
-       WHEN name LIKE '%log %' THEN 'log'
-       WHEN name LIKE '%config%' THEN 'config'
-       WHEN name LIKE '%rev-parse%' THEN 'rev_parse'
-       ELSE 'other' END as task_type,
-  COUNT(*) as count,
-  ROUND(SUM(dur)/1e6, 2) as total_ms,
-  ROUND(MAX(dur)/1e6, 2) as max_ms,
-  ROUND(AVG(dur)/1e6, 2) as avg_ms
-FROM slice WHERE dur > 0
-GROUP BY task_type ORDER BY total_ms DESC;
-EOF
-trace_processor trace.json -q /tmp/q.sql
-
-# 2. How parallel are we? — subprocess time vs subprocess span
-# parallelism ≈ 1.0 → serial; higher → concurrent execution is helping
-# (span = first subprocess start to last subprocess end; excludes wt's non-subprocess overhead)
-cat > /tmp/q.sql << 'EOF'
-SELECT
-  ROUND(SUM(dur)/1e6, 1) as total_subprocess_ms,
-  ROUND((MAX(ts + dur) - MIN(ts))/1e6, 1) as span_ms,
-  ROUND(CAST(SUM(dur) AS FLOAT) / (MAX(ts + dur) - MIN(ts)), 1) as parallelism
-FROM slice WHERE dur > 0;
-EOF
-trace_processor trace.json -q /tmp/q.sql
-
-# 3. What's on the critical path? — phase durations
-# Shows time between milestones: serial setup, parallel work, finalization
-# Key milestones: "Skeleton rendered", "Parallel execution started", "All results drained"
-cat > /tmp/q.sql << 'EOF'
-SELECT
-  name,
-  ROUND(ts/1e6, 1) as ms,
-  ROUND((ts - LAG(ts) OVER (ORDER BY ts))/1e6, 1) as phase_ms
-FROM slice WHERE dur = 0
-ORDER BY ts;
-EOF
-trace_processor trace.json -q /tmp/q.sql
-
-# 3. What's on the critical path? — parallel bottleneck (per-worktree)
-# The worktree with the highest total_ms is the likely parallel bottleneck
-cat > /tmp/q.sql << 'EOF'
-SELECT
-  EXTRACT_ARG(arg_set_id, 'args.context') as worktree,
-  COUNT(*) as commands,
-  ROUND(SUM(dur)/1e6, 1) as total_ms
-FROM slice WHERE dur > 0
-GROUP BY worktree ORDER BY total_ms DESC;
-EOF
-trace_processor trace.json -q /tmp/q.sql
-```
+3. **What's on the critical path?** The critical path passes through serial phases (setup, finalization) plus the slowest work item in the parallel phase. The profile's `phases` (milestone gaps) and `by_context` (per-worktree totals — the worktree with the highest total is the likely parallel bottleneck) bound it, but the trace format doesn't capture task dependencies, so visualizing the trace in Perfetto is more useful here.
 
 ### Generating traces from benchmark repos