From b22aced85df275b783d9fbe9c7801500f68182d5 Mon Sep 17 00:00:00 2001 From: Maximilian Roos Date: Thu, 9 Jul 2026 20:14:21 -0700 Subject: [PATCH 1/6] docs(design): propose canonicalizing the benchmark / wt-perf system Design proposal (review-only, per design/ convention). Inventories the five perf-tooling layers and proposes seven consolidations: delete the cache-check subcommand (subsumed by logs profile --format=json), move the timeline renderer into worktrunk::trace, add by_context to Profile and retire the trace_processor SQL section, share one warm/cold bench runner, prune the bench matrix (~15-20 min/day of CI), move the wt-perf CLI tests in-package, and unify the setup config parser. Emission, chrome.rs, the separate wt-perf package, and fixture shapes stay as is. Co-Authored-By: Claude Fable 5 --- design/simplify-bench-perf.md | 220 ++++++++++++++++++++++++++++++++++ 1 file changed, 220 insertions(+) create mode 100644 design/simplify-bench-perf.md diff --git a/design/simplify-bench-perf.md b/design/simplify-bench-perf.md new file mode 100644 index 000000000..0a4d7ce65 --- /dev/null +++ b/design/simplify-bench-perf.md @@ -0,0 +1,220 @@ +# Design: canonicalize the benchmark / wt-perf system + +Status: proposal (no production code). This answers one question: + +> The perf tooling has grown five layers: trace emission, the analysis library +> in `src/trace/`, the `wt-perf` helper crate, seven Criterion bench targets +> with a daily CI run, and `benches/CLAUDE.md`. Where do they duplicate each +> other, and what can be canonicalized or cut without losing meaningful +> capability? + +Short answer: the emission side (`src/trace/emit.rs` and the `CommandTrace` +chokepoint) is already canonical and stays untouched. The duplication is on the +*consumption* side: two CLIs expose the same analysis, the timeline renderer +re-implements label formatting the library already owns, the one analysis the +library doesn't compute keeps an 80-line SQL section alive in +`benches/CLAUDE.md`, the warm/cold iteration pattern is copy-pasted across five +bench files, and three bench groups guard the same regression shape. Each +proposal below deletes one of those parallel paths. + +## Summary of recommendations + +1. **Delete `wt-perf cache-check`.** Its output is the `cache` field of + `wt config state logs profile --format=json`: the same `CacheReport`, + built from the same entries. +2. **Move the timeline renderer into `worktrunk::trace`** and render it with + the library's existing label/table/duration helpers. `wt-perf` keeps the + harness work (spawn `wt -vv`, external wall clock, cold invalidation) and + delegates all rendering. +3. **Add a `by_context` table to `Profile`, then cut the trace_processor SQL + section from `benches/CLAUDE.md`.** Per-worktree subprocess totals are the + only documented query `logs profile` doesn't already answer. +4. **One shared warm/cold bench runner in `wt_perf`.** Hoist `run_benchmark` + from `benches/list.rs` into the library; the `PerIteration` rationale is + written once, on the helper, instead of five times across bench files. +5. **Prune the bench matrix**: `real_repo` keeps only the 8-worktree variants, + `cow_copy` is deleted, and the `remove_e2e/first_output` arm (a duplicate of + `first_output/remove`) is deleted. Saves roughly 15–20 minutes of the ~80 + minute daily run. +6. **Move the `wt-perf` CLI tests into the `wt-perf` package.** In-package + integration tests get `CARGO_BIN_EXE_wt-perf` natively, which retires the + dummy `builds.rs` and drops `wt-perf` from the nextest setup script. +7. **Fold `mixed-W-B` into `parse_config`** so `wt-perf setup` has one config + parser instead of a parser plus a special case. + +Items 1–4 and 6–7 are pure consolidation (no signal lost). Item 5 trades named +benchmark series for CI time; the losses are itemized below and each has a +covering twin or a documented fallback. + +## The system today + +| Layer | Where | Size | Role | +|-------|-------|------|------| +| Emission | `src/trace/emit.rs` + `src/logging.rs` layers | 435 | `CommandTrace`/`Span`/`instant` → `trace.jsonl` / `trace.log` | +| Analysis library | `src/trace/{parse,profile,chrome}.rs` | ~2,060 | parse back; `Profile`/`CacheReport`; Chrome Trace export | +| wt-perf crate | `tests/helpers/wt-perf/` | ~1,530 | fixture builders (lib) + CLI: `setup`, `invalidate`, `trace`, `cache-check`, `timeline` | +| Benches | `benches/*.rs` (7 targets) | 1,255 | Criterion; daily `benchmarks.yaml` run (~80 min) feeding the gist time series | +| Docs | `benches/CLAUDE.md` | 352 | run examples, cache handling, fixture notes, trace_processor SQL | + +Analysis consumers: `wt config state logs profile` (text + JSON), `wt diagnose` +(embeds the rendered profile), and the `wt-perf` CLI. + +The canonicalization principle the proposals converge on: **capture and +harness work lives in `wt-perf`; analysis lives in `worktrunk::trace` with +`wt config state logs profile` as its one CLI surface.** `wt-perf timeline` +earns its place because it does harness work a passive reader can't (spawn +under `-vv`, measure spawn→wait wall externally, invalidate for cold runs); +`cache-check` doesn't, because it's a passive reader of the same file +`logs profile` reads. + +## Proposals + +### 1. Delete `wt-perf cache-check` + +`cache_check()` in `tests/helpers/wt-perf/src/main.rs` is +`CacheReport::from_entries` + `serde_json::to_string_pretty`. `handle_logs_profile` +with `--format=json` serializes `Profile`, whose `cache` field is the same +struct from the same entries. Two documented entry points for one analysis; +`jq .cache` closes the gap. Delete the subcommand and its `after_long_help`. + +### 2. One renderer per view: move the timeline into `worktrunk::trace` + +`render_timeline`/`describe` in `wt-perf/src/main.rs` (~120 lines plus +snapshots) duplicate the library: + +- `describe()` re-implements `profile.rs::command_label` (the `cmd [ctx]` + + `(ok=false)` / `(err: …)` shape), and the two have already drifted: the + timeline pads two spaces before the failure marker, the profile one. +- The timeline aligns columns with `tabwriter` while `profile.rs` has its own + `render_table`; durations render via `Duration`'s `Debug` (`4.5ms`, `1.5s`) + in one and fixed-point `fmt_dur` (`4.50ms`) in the other. + +Move the renderer into `src/trace/` as +`render_timeline(&[TraceEntry], wall: Duration) -> String`, built on +`command_label`, `render_table`, and `fmt_dur`. `wt-perf timeline` keeps the +spawn/invalidate/measure logic and calls it. The `tabwriter` dependency and the +duplicated label code go away; timeline durations switch to the fixed-point +format (a cosmetic change to a dev tool's output). + +Also under this item: the `logs profile` help currently points users at +`cargo run -p wt-perf -- timeline`, a tool that exists only in this repo. Move +that pointer to `benches/CLAUDE.md`, where every reader can actually run it. + +### 3. `by_context` in `Profile`; retire the SQL section + +`benches/CLAUDE.md` carries ~80 lines of trace_processor SQL for three +questions. `Profile` already answers nearly all of it: + +| CLAUDE.md query | Profile field | +|-----------------|---------------| +| #1 slowest individual commands | `slowest` | +| #1 total time by command type (hand-rolled `CASE` buckets) | `by_type` (via `command_type`, which the SQL approximates) | +| #2 parallelism factor | `parallelism`, `peak_concurrency` | +| #3 phase durations from milestones | `phases`, `key_intervals` | +| #3 per-worktree totals (`EXTRACT_ARG(args.context)`) | **missing** | + +Add `by_context: Vec` (context, count, total; busiest first) to +`Profile` — a few lines in `from_entries`, one more table in `render_text`, +one more array in the JSON. Then the SQL section reduces to one line: open the +Chrome JSON in Perfetto for visual critical-path inspection, which is the one +thing SQL-over-slices was never good at anyway (the section itself says so). +The `command_type` bucketing also stops having a hand-maintained SQL shadow +that must track new command shapes. + +`chrome.rs` stays: Perfetto visualization is the remaining consumer and has no +substitute. + +### 4. One warm/cold bench runner + +`benches/list.rs` has `run_benchmark` (binary, repo, cold flag, args, env); +`remove.rs`, `picker_preview.rs`, `alias.rs`, and `time_to_first_output.rs` +re-inline the same warm/cold split, and each copy carries its own multi-line +retelling of why `BatchSize::PerIteration` beats `SmallInput`. Hoist the +helper into the `wt_perf` library (it already owns `invalidate_caches_auto`, +the other half of the pattern), document the `PerIteration` rationale once on +it, and add the success assertion most call sites bolt on. Bench files keep +only what's genuinely per-bench: fixtures, args, and setup closures like +`recreate_worktree`. + +`benches/CLAUDE.md`'s "Cache Handling" section then references the helper +instead of prescribing the pattern for hand-rolling. + +### 5. Prune the bench matrix + +The daily run costs ~80 minutes. Three cuts where cost × redundancy is +highest: + +- **`real_repo`: keep `{warm,cold}/8`, drop the 1- and 4-worktree variants.** + Each variant clones rust-lang/rust locally and the cold ones rebuild + 59k-entry indexes per iteration; this group dominates the run. The + worktree-count scaling *shape* is already tracked at criterion cadence by + `worktree_scaling` (1/4/8, synthetic); what's unique to `real_repo` is + real-repo magnitude and the cold penalty, which the 8-worktree endpoints + keep. Lost: the real-repo scaling curve's interior points. +- **Delete `cow_copy`.** It compares production `copy_dir_recursive` against a + 40-line serial copy that exists only inside the bench — a shadow + implementation maintained to validate a settled design choice (rayon + parallel copy). Six size/shape variants × 2 impls at daily cadence guard a + code path that changes only when `reflink_copy` or the copy loop does. + Lost: a throughput series for `wt step copy-ignored`. If that loss bites, + the fallback is re-adding a single parallel-only variant. +- **Delete the `remove_e2e/first_output` arm.** Its own comment says it is + "the same as time_to_first_output"; two series measure one quantity from two + files. The cross-group comparison (`remove_e2e/no_hooks` vs + `first_output/remove`) still works — both land in the same gist. + +Considered and skipped: thinning `skeleton`/`worktree_scaling` to 1-and-8. +They're cheap (modest fixture, 15s budgets), and the interior point is what +distinguishes linear from superlinear drift. + +### 6. Move the wt-perf CLI tests into the wt-perf package + +`tests/integration_tests/analyze_trace.rs` (four tests of `wt-perf trace`) +lives in the main integration suite, so it reaches the binary through +`workspace_bin()` — which is why the nextest setup script pre-builds `wt-perf` +and why the crate carries a dummy `tests/builds.rs` whose only job is forcing +binary compilation. Integration tests *inside* the `wt-perf` package get +`CARGO_BIN_EXE_wt-perf` from cargo directly, and building them builds the +binary. Move the four tests there; delete `builds.rs` (the real tests now do +its job); drop `wt-perf` from `.config/nextest.toml`'s setup script (mock-stub +still needs the layer, so the script itself stays). + +Behavior change: `cargo test --test integration` no longer runs these four +tests; full-workspace runs (the gate, CI, `cargo nextest run`) still do, since +`wt-perf` is in `default-members`. + +### 7. One config parser in `wt-perf setup` + +`parse_config` handles `typical-N`/`branches-N[-M]`/`divergent`/`picker-test`; +`mixed-W-B` is parsed by a separate `parse_mixed` in `main.rs` with its own +`match` arm and an `unreachable!`. Return an enum +(`Flat(RepoConfig)` / `Mixed { worktrees, branches }`) from `parse_config` and +the special case collapses. The fixture builders themselves +(`create_repo_at` vs `create_mixed_repo_at`) share only trivial plumbing (init, +auto-maintenance config, gc) — worth a small shared `init_repo` helper, but no +deeper unification: their fixture shapes are deliberately different, and +reshaping fixtures moves every benchmark's level in the gist time series. + +## What stays as is + +- **Emission** (`emit.rs`, the `CommandTrace` chokepoint, the two-rendering + split in `logging.rs`): already single-path by design. +- **The wt-perf binary as a separate package.** Folding its commands into `wt` + would ship fixture generators to users, and cargo-dist ships every `[[bin]]` + in the main crate (the documented reason the helper packages exist). +- **Seven separate `[[bench]]` targets.** Merging them saves link time but + costs per-target compile selectivity (`cargo bench --bench list` builds one + target), which matters more during iteration. +- **`wt-perf trace`** (jsonl → Chrome JSON for an already-captured file, e.g. a + CI artifact): the file-input twin of `timeline --chrome`, five lines of CLI + over the library. +- **Fixture shapes and surviving benchmark IDs**: the gist time series keys on + them. + +## Sequencing + +Items 1–4, 6, 7 are one consolidation PR each (or one combined); no series is +affected. Item 5 ends three series and should land as its own PR so the +discontinuity in the gist has a single date and commit to point at. +`benches/CLAUDE.md` shrinks in the same PRs that obsolete its sections (the +SQL section with item 3, the hand-rolled cache-handling pattern with item 4). From 86ef932e59dfba6d910344600234f4155bef64fa Mon Sep 17 00:00:00 2001 From: Maximilian Roos Date: Thu, 9 Jul 2026 20:49:28 -0700 Subject: [PATCH 2/6] refactor(perf): canonicalize the benchmark / wt-perf system MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Implements design/simplify-bench-perf.md (items 1-7): 1. Delete wt-perf cache-check — its output is the .cache field of wt config state logs profile --format=json. 2. Move the timeline renderer into worktrunk::trace, sharing command_label/render_table/fmt_dur with the profile so the two views can't drift (drops wt-perf's tabwriter and insta deps; timeline durations now render in the profile's fixed-point format). 3. Add by_context to Profile (BY CONTEXT table + JSON array): per-worktree subprocess totals, the one analysis that previously required trace_processor SQL. benches/CLAUDE.md's SQL section becomes a pointer to logs profile + Perfetto; the running-tend statusline recipe now uses logs profile too. 4. One warm/cold bench runner (wt_perf::bench_wt) owns the BatchSize::PerIteration rationale once; five inline copies deleted. All runs now assert child exit status (list.rs previously ignored it). 5. Prune the matrix: real_repo keeps only the 8-worktree variants, cow_copy is deleted (shadow serial impl validating a settled choice), and the remove_e2e/first_output arm (duplicate of first_output/remove) is deleted. Ends three gist series; saves ~15-20 min/day of bench CI. 6. Move the wt-perf CLI tests in-package (native CARGO_BIN_EXE_wt-perf), deleting the dummy builds.rs and dropping wt-perf from the nextest setup script. 7. parse_config returns a SetupConfig enum covering mixed-W-B; shared init_bench_repo plumbing between the two fixture builders. Co-Authored-By: Claude Fable 5 --- .claude/skills/running-tend/SKILL.md | 14 +- .config/nextest.toml | 43 +-- CHANGELOG.md | 2 + Cargo.lock | 12 +- Cargo.toml | 8 +- benches/CLAUDE.md | 126 ++------ benches/alias.rs | 41 +-- benches/cow_copy.rs | 170 ----------- benches/list.rs | 130 +++----- benches/picker_preview.rs | 46 +-- benches/remove.rs | 37 +-- benches/time_to_first_output.rs | 46 +-- src/cli/config.rs | 4 +- src/testing/mod.rs | 8 +- src/trace/mod.rs | 2 + src/trace/profile.rs | 87 +++++- ...__profile__tests__renders_full_report.snap | 5 + ...truncates_slowest_and_collapses_cache.snap | 5 + src/trace/timeline.rs | 215 +++++++++++++ tests/helpers/wt-perf/Cargo.toml | 16 +- tests/helpers/wt-perf/src/lib.rs | 162 +++++++--- tests/helpers/wt-perf/src/main.rs | 287 ++---------------- tests/helpers/wt-perf/tests/builds.rs | 5 - .../wt-perf/tests/cli.rs} | 10 +- tests/integration_tests/config_state.rs | 12 + tests/integration_tests/mod.rs | 1 - ...config_state__logs_profile_from_stdin.snap | 5 + ..._help__help_config_state_logs_profile.snap | 6 +- 28 files changed, 609 insertions(+), 896 deletions(-) delete mode 100644 benches/cow_copy.rs create mode 100644 src/trace/timeline.rs delete mode 100644 tests/helpers/wt-perf/tests/builds.rs rename tests/{integration_tests/analyze_trace.rs => helpers/wt-perf/tests/cli.rs} (94%) diff --git a/.claude/skills/running-tend/SKILL.md b/.claude/skills/running-tend/SKILL.md index 81b7484d7..7b0b41505 100644 --- a/.claude/skills/running-tend/SKILL.md +++ b/.claude/skills/running-tend/SKILL.md @@ -287,9 +287,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 @@ -299,12 +299,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, diff --git a/.config/nextest.toml b/.config/nextest.toml index 580e39789..b45c5c1a7 100644 --- a/.config/nextest.toml +++ b/.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_`, 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_`, 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" diff --git a/CHANGELOG.md b/CHANGELOG.md index 659a82b8e..327035b19 100644 --- a/CHANGELOG.md +++ b/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. ## 0.66.0 diff --git a/Cargo.lock b/Cargo.lock index 4ad9004ff..580745de3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3325,15 +3325,6 @@ dependencies = [ "unicode-width 0.2.2", ] -[[package]] -name = "tabwriter" -version = "1.4.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "fce91f2f0ec87dff7e6bcbbeb267439aa1188703003c6055193c821487400432" -dependencies = [ - "unicode-width 0.2.2", -] - [[package]] name = "tempfile" version = "3.27.0" @@ -4608,10 +4599,9 @@ name = "wt-perf" version = "0.1.0" dependencies = [ "clap", + "criterion", "dunce", - "insta", "serde_json", - "tabwriter", "tempfile", "worktrunk", ] diff --git a/Cargo.toml b/Cargo.toml index ab89f5638..74a396d1d 100644 --- a/Cargo.toml +++ b/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 @@ -329,10 +331,6 @@ harness = false name = "list" harness = false -[[bench]] -name = "cow_copy" -harness = false - [[bench]] name = "time_to_first_output" harness = false diff --git a/benches/CLAUDE.md b/benches/CLAUDE.md index 94aaabf84..bf6af9654 100644 --- a/benches/CLAUDE.md +++ b/benches/CLAUDE.md @@ -47,7 +47,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 @@ -79,21 +79,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: @@ -227,103 +217,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 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 diff --git a/benches/alias.rs b/benches/alias.rs index e17c44ea4..993e4e971 100644 --- a/benches/alias.rs +++ b/benches/alias.rs @@ -33,7 +33,7 @@ use criterion::{BenchmarkId, Criterion, criterion_group, criterion_main}; use std::path::Path; use std::process::Command; use worktrunk::testing::isolate_subprocess_env; -use wt_perf::{RepoConfig, create_repo, invalidate_caches_auto}; +use wt_perf::{RepoConfig, bench_wt, create_repo, run_and_check}; /// Alias body is a shell builtin so the wall-clock is dominated by the /// parent's dispatch — not by running a real subcommand. @@ -73,16 +73,6 @@ fn wt_cmd(binary: &Path, repo: &Path, user_config: &Path, args: &[&str]) -> Comm cmd } -/// Run a benchmark command and assert success, surfacing stderr on failure. -fn run_and_check(mut cmd: Command, label: &str) { - let output = cmd.output().unwrap(); - assert!( - output.status.success(), - "{label} failed: {}", - String::from_utf8_lossy(&output.stderr) - ); -} - fn bench_dispatch(c: &mut Criterion) { let mut group = c.benchmark_group("dispatch"); let binary = Path::new(env!("CARGO_BIN_EXE_wt")); @@ -95,7 +85,7 @@ fn bench_dispatch(c: &mut Criterion) { let mut cmd = Command::new(binary); cmd.arg("--version"); isolate_subprocess_env(&mut cmd, None); - run_and_check(cmd, "wt_version"); + run_and_check(&mut cmd); }); }); @@ -122,27 +112,12 @@ fn bench_dispatch(c: &mut Criterion) { }; group.bench_with_input(BenchmarkId::new(id, worktrees), &worktrees, |b, _| { - let run = || { - run_and_check( - wt_cmd(binary, &repo_path, user_config, &[alias_name]), - "dispatch", - ); - }; - if cold { - // `PerIteration` so every measured run is actually - // cold — `build_hook_context` resolves the default - // branch, which writes `worktrunk.default-branch` - // and would be a cache hit on iters 2-N under - // `SmallInput`. See `benches/CLAUDE.md` → - // "Cache Handling" for the full rationale. - b.iter_batched( - || invalidate_caches_auto(&repo_path), - |_| run(), - criterion::BatchSize::PerIteration, - ); - } else { - b.iter(run); - } + // Cold matters here: `build_hook_context` resolves the + // default branch, which writes `worktrunk.default-branch` + // and would otherwise be a cache hit on iters 2-N. + bench_wt(b, &repo_path, cold, || { + wt_cmd(binary, &repo_path, user_config, &[alias_name]) + }); }); } } diff --git a/benches/cow_copy.rs b/benches/cow_copy.rs deleted file mode 100644 index 53c63f3b7..000000000 --- a/benches/cow_copy.rs +++ /dev/null @@ -1,170 +0,0 @@ -// Benchmarks for `wt step copy-ignored` COW directory copying -// -// Compares serial vs the production parallel (rayon) recursive directory copying. -// Two directory layouts test different parallelism profiles: -// -// - deep: Rust target/ with most files in a single deps/ dir (narrow tree) -// - wide: Files spread across many subdirectories (wide tree) -// -// Run: -// cargo bench --bench cow_copy -// cargo bench --bench cow_copy -- serial # serial only -// cargo bench --bench cow_copy -- parallel # parallel only -// cargo bench --bench cow_copy -- wide # wide tree only - -use criterion::{BenchmarkId, Criterion, criterion_group, criterion_main}; -use std::path::Path; -use tempfile::TempDir; -use worktrunk::copy::copy_dir_recursive; -use worktrunk::progress::Progress; - -/// Create a narrow directory structure mimicking a Rust target/ directory. -/// -/// Most files concentrate in debug/deps/ — exercises parallelism within a single -/// large directory. -fn create_deep_target(file_count: usize) -> TempDir { - let temp = tempfile::tempdir().unwrap(); - let target = temp.path().join("target"); - - let subdirs = [ - "debug/deps", - "debug/build", - "debug/incremental", - "release/deps", - ]; - for subdir in &subdirs { - std::fs::create_dir_all(target.join(subdir)).unwrap(); - } - - let mut created = 0; - let deps_dir = target.join("debug/deps"); - - while created < file_count { - let rlib = deps_dir.join(format!("libcrate_{:04}.rlib", created)); - std::fs::write(&rlib, vec![0u8; 100_000]).unwrap(); - created += 1; - - if created >= file_count { - break; - } - - let rmeta = deps_dir.join(format!("libcrate_{:04}.rmeta", created)); - std::fs::write(&rmeta, vec![0u8; 10_000]).unwrap(); - created += 1; - - if created >= file_count { - break; - } - - let dep = deps_dir.join(format!("libcrate_{:04}.d", created)); - std::fs::write(&dep, vec![0u8; 500]).unwrap(); - created += 1; - } - - let incr = target.join("debug/incremental/crate_name-hash"); - std::fs::create_dir_all(&incr).unwrap(); - for i in 0..10 { - std::fs::write(incr.join(format!("s-abc123-{}.lock", i)), "").unwrap(); - } - - temp -} - -/// Create a wide directory tree with files distributed across many subdirectories. -/// -/// Exercises parallelism across sibling directories — the primary benefit of -/// rayon in copy_dir_recursive. -fn create_wide_target(file_count: usize) -> TempDir { - let temp = tempfile::tempdir().unwrap(); - let target = temp.path().join("target"); - - let files_per_dir = 10; - let dir_count = file_count / files_per_dir; - let mut created = 0; - - for d in 0..dir_count { - let subdir = target.join(format!("pkg_{:04}", d)); - std::fs::create_dir_all(&subdir).unwrap(); - - for f in 0..files_per_dir { - if created >= file_count { - return temp; - } - let file = subdir.join(format!("file_{:02}.dat", f)); - std::fs::write(&file, vec![0u8; 50_000]).unwrap(); - created += 1; - } - } - - temp -} - -/// Serial baseline: sequential file-by-file copy without rayon. -fn copy_dir_serial(src: &Path, dest: &Path) -> std::io::Result<()> { - std::fs::create_dir_all(dest)?; - for entry in std::fs::read_dir(src)? { - let entry = entry?; - let file_type = entry.file_type()?; - let src_path = entry.path(); - let dest_path = dest.join(entry.file_name()); - - if file_type.is_dir() { - copy_dir_serial(&src_path, &dest_path)?; - } else if file_type.is_file() { - reflink_copy::reflink_or_copy(src_path, &dest_path)?; - } - } - Ok(()) -} - -fn bench_helper( - group: &mut criterion::BenchmarkGroup, - label: &str, - file_count: usize, - create_fn: fn(usize) -> TempDir, -) { - let temp = create_fn(file_count); - let src = temp.path().join("target"); - - group.bench_with_input( - BenchmarkId::new(format!("serial/{label}"), file_count), - &src, - |b, src| { - let mut iter = 0u64; - b.iter(|| { - let dest = temp.path().join(format!("copy_s_{}", iter)); - iter += 1; - copy_dir_serial(src, &dest).unwrap(); - std::fs::remove_dir_all(&dest).ok(); - }); - }, - ); - - group.bench_with_input( - BenchmarkId::new(format!("parallel/{label}"), file_count), - &src, - |b, src| { - let mut iter = 0u64; - b.iter(|| { - let dest = temp.path().join(format!("copy_p_{}", iter)); - iter += 1; - copy_dir_recursive(src, &dest, None, false, &Progress::disabled()).unwrap(); - std::fs::remove_dir_all(&dest).ok(); - }); - }, - ); -} - -fn bench_copy_target(c: &mut Criterion) { - let mut group = c.benchmark_group("copy_target"); - - for &file_count in &[100, 500, 1000] { - bench_helper(&mut group, "deep", file_count, create_deep_target); - bench_helper(&mut group, "wide", file_count, create_wide_target); - } - - group.finish(); -} - -criterion_group!(benches, bench_copy_target); -criterion_main!(benches); diff --git a/benches/list.rs b/benches/list.rs index d0044020e..2b446fbae 100644 --- a/benches/list.rs +++ b/benches/list.rs @@ -7,18 +7,17 @@ // in varied states, with branch divergence spread across history depth. // The realistic "everything at once" workload (warm + cold). // - divergent_branches: 200 branches × 20 commits / GH #461 deep-divergence stress (warm + cold) -// - real_repo: rust-lang/rust clone (1, 4, 8 worktrees; warm + cold) +// - real_repo: rust-lang/rust clone (8 worktrees; warm + cold) // - real_repo_many_branches: 50 branches at different history depths / GH #461 // - warm: all branches (first run expensive; subsequent runs hit persistent cache) // - warm_worktrees_only: no branch enumeration (~600ms) // // Attribution: a `full` wall time can't be split by side (worktree- and // branch-side git subprocesses overlap on the rayon pool), so to see where a -// regression lands, trace one invocation and bucket subprocess time per -// worktree / task type — see `benches/CLAUDE.md` ("Performance Investigation -// with wt-perf", query #3, `args.context`). For per-side regression tracking -// at criterion cadence, `worktree_scaling` is the worktree side and -// `divergent_branches` the branch side. +// regression lands, trace one invocation and read the profile's BY CONTEXT / +// BY COMMAND TYPE tables — see `benches/CLAUDE.md` ("Analyzing a trace"). +// For per-side regression tracking at criterion cadence, `worktree_scaling` +// is the worktree side and `divergent_branches` the branch side. // // Run examples (Criterion takes a positional substring FILTER; no --skip): // cargo bench --bench list # All benchmarks @@ -33,8 +32,8 @@ use std::path::{Path, PathBuf}; use std::process::Command; use worktrunk::testing::isolate_subprocess_env; use wt_perf::{ - RepoConfig, add_history_spread_branches, add_worktrees, clone_rust_repo, create_mixed_repo, - create_repo, invalidate_caches_auto, run_git, setup_fake_remote, + RepoConfig, add_history_spread_branches, add_worktrees, bench_wt, clone_rust_repo, + create_mixed_repo, create_repo, run_git, setup_fake_remote, }; /// Benchmark configuration wrapping RepoConfig with cache state. @@ -67,9 +66,7 @@ impl BenchConfig { /// Run `wt` with `args` in `repo_path`, on a warm or cold cache. /// /// Fixture-agnostic: callers build whatever repo shape they want, then pass -/// `cold_cache` to pick the iteration strategy. Warm uses plain `b.iter` -/// (caches stay warm across iterations); cold invalidates before every -/// measured iteration. +/// `cold_cache` to pick the iteration strategy (see [`bench_wt`]). fn run_benchmark( b: &mut criterion::Bencher, binary: &Path, @@ -78,7 +75,7 @@ fn run_benchmark( args: &[&str], env: Option<(&str, &str)>, ) { - let cmd_factory = || { + bench_wt(b, repo_path, cold_cache, || { let mut cmd = Command::new(binary); cmd.args(args).current_dir(repo_path); isolate_subprocess_env(&mut cmd, None); @@ -86,28 +83,7 @@ fn run_benchmark( cmd.env(key, value); } cmd - }; - - if cold_cache { - // `BatchSize::PerIteration` (not `SmallInput`): under `SmallInput`, - // criterion calls `setup` for an entire batch up front and then runs - // the timed routines back-to-back — so only the first `wt` per batch - // is cold and the rest hit a freshly populated `.git/wt/cache/`, - // biasing "cold" warm. `PerIteration` invalidates immediately before - // every measured iteration; the setup is far cheaper than a `wt` - // subprocess, so per-iter `Instant::now` overhead doesn't dominate. - b.iter_batched( - || invalidate_caches_auto(repo_path), - |_| { - cmd_factory().output().unwrap(); - }, - criterion::BatchSize::PerIteration, - ); - } else { - b.iter(|| { - cmd_factory().output().unwrap(); - }); - } + }); } fn bench_skeleton(c: &mut Criterion) { @@ -169,59 +145,41 @@ fn bench_real_repo(c: &mut Criterion) { let mut group = c.benchmark_group("real_repo"); // `wt list` on rust-lang/rust runs ~2s warm — dominated by one deep // `git for-each-ref %(ahead-behind:main)` walk — and several times - // that for cold/8, where each iteration also rebuilds eight 59k-entry + // that for cold, where each iteration also rebuilds eight 59k-entry // indexes via `git status`. Warm-path variance is that slowest single // subprocess, not measurement noise, so the inherited 30-sample / 15s // default just burns time: at >1s/iter Criterion can't fit 30 samples // in 15s, so it runs 30 single-iteration samples regardless. 10 is - // Criterion's minimum (`sample_size` < 10 panics); the 20s budget - // caps the cheap warm variants at ≤2 iterations per sample. Cuts the - // group's measured time ~3× — the expensive cold variants drop from - // 30 iterations to 10. + // Criterion's minimum (`sample_size` < 10 panics). + // + // 8 worktrees only: the worktree-count scaling shape is tracked at + // criterion cadence by `worktree_scaling` (synthetic, 1/4/8); what's + // unique here is real-repo magnitude and the cold penalty, which the + // 8-worktree endpoints keep — each extra variant costs a fresh local + // clone of rust-lang/rust plus its measurement window. group.measurement_time(std::time::Duration::from_secs(20)); group.sample_size(10); let binary = Path::new(env!("CARGO_BIN_EXE_wt")); + let worktrees = 8; - for worktrees in [1, 4, 8] { - for cold in [false, true] { - let label = if cold { "cold" } else { "warm" }; + for cold in [false, true] { + let label = if cold { "cold" } else { "warm" }; - group.bench_with_input( - BenchmarkId::new(label, worktrees), - &(worktrees, cold), - |b, &(worktrees, cold)| { - let config = RepoConfig::typical(worktrees); - let temp = tempfile::tempdir().unwrap(); - let workspace_main = clone_rust_repo(&temp); - add_worktrees(&config, &workspace_main); - run_git(&workspace_main, &["status"]); - - let make_cmd = || { - let mut cmd = Command::new(binary); - cmd.arg("list").current_dir(&workspace_main); - isolate_subprocess_env(&mut cmd, None); - cmd - }; - - if cold { - // `PerIteration` so every measured run is actually - // cold — see `run_benchmark` above for the rationale. - b.iter_batched( - || invalidate_caches_auto(&workspace_main), - |_| { - make_cmd().output().unwrap(); - }, - criterion::BatchSize::PerIteration, - ); - } else { - b.iter(|| { - make_cmd().output().unwrap(); - }); - } - }, - ); - } + group.bench_with_input(BenchmarkId::new(label, worktrees), &cold, |b, &cold| { + let config = RepoConfig::typical(worktrees); + let temp = tempfile::tempdir().unwrap(); + let workspace_main = clone_rust_repo(&temp); + add_worktrees(&config, &workspace_main); + run_git(&workspace_main, &["status"]); + + bench_wt(b, &workspace_main, cold, || { + let mut cmd = Command::new(binary); + cmd.arg("list").current_dir(&workspace_main); + isolate_subprocess_env(&mut cmd, None); + cmd + }); + }); } group.finish(); @@ -316,23 +274,23 @@ fn bench_real_repo_many_branches(c: &mut Criterion) { // Baseline: all branches group.bench_function("warm", |b| { let (_temp, workspace_main) = setup_workspace(); - b.iter(|| { + bench_wt(b, &workspace_main, false, || { let mut cmd = Command::new(binary); cmd.args(["list", "--branches"]) .current_dir(&workspace_main); isolate_subprocess_env(&mut cmd, None); - cmd.output().unwrap(); + cmd }); }); // Worktrees only: no branch enumeration, skips expensive %(ahead-behind) batch group.bench_function("warm_worktrees_only", |b| { let (_temp, workspace_main) = setup_workspace(); - b.iter(|| { + bench_wt(b, &workspace_main, false, || { let mut cmd = Command::new(binary); cmd.arg("list").current_dir(&workspace_main); // no --branches isolate_subprocess_env(&mut cmd, None); - cmd.output().unwrap(); + cmd }); }); @@ -350,11 +308,11 @@ fn bench_real_repo_many_branches(c: &mut Criterion) { /// history depth, so the `git for-each-ref %(ahead-behind)` walk has real /// history to traverse). /// -/// To see *where* a regression lands, trace one invocation and bucket -/// subprocess time per worktree / task type — see `benches/CLAUDE.md` -/// ("Performance Investigation with wt-perf", query #3, `args.context`); a -/// criterion wall time can't be decomposed by side because the worktree- and -/// branch-side git subprocesses run concurrently on the rayon pool. For +/// To see *where* a regression lands, trace one invocation and read the +/// profile's BY CONTEXT / BY COMMAND TYPE tables — see `benches/CLAUDE.md` +/// ("Analyzing a trace"); a criterion wall time can't be decomposed by side +/// because the worktree- and branch-side git subprocesses run concurrently on +/// the rayon pool. For /// per-side regression tracking at criterion cadence, `worktree_scaling` /// isolates the worktree side and `divergent_branches` the branch-side walk. /// diff --git a/benches/picker_preview.rs b/benches/picker_preview.rs index f6924b09f..f0620334f 100644 --- a/benches/picker_preview.rs +++ b/benches/picker_preview.rs @@ -51,7 +51,7 @@ use std::process::Command; #[cfg(unix)] use worktrunk::testing::isolate_subprocess_env; #[cfg(unix)] -use wt_perf::{RepoConfig, create_repo, invalidate_caches_auto, setup_fake_remote}; +use wt_perf::{RepoConfig, bench_wt, create_repo, setup_fake_remote}; #[cfg(unix)] fn bench_picker_preview(c: &mut Criterion) { @@ -88,45 +88,11 @@ fn bench_picker_preview(c: &mut Criterion) { cmd }; - if *cold { - // The picker writes to `.git/wt/cache/picker-preview/` - // (Log / BranchDiff / UpstreamDiff entries). Without - // invalidation, iter 1 measures real cost and iter 2+ - // measure cache hits. - // - // `BatchSize::PerIteration` (not `SmallInput`): - // under `SmallInput`, criterion calls `setup` for an - // entire batch up front and then runs the timed - // routines back-to-back — so the first `wt switch` - // in a batch is cold but the rest hit a freshly - // populated `.git/wt/cache/`, biasing the "cold" - // measurement warm. `PerIteration` invalidates - // immediately before every measured iteration; the - // setup itself is far cheaper than a `wt switch` - // invocation, so per-iteration `Instant::now` - // overhead doesn't dominate. - b.iter_batched( - || invalidate_caches_auto(&repo_path), - |_| { - let output = make_cmd().output().unwrap(); - assert!( - output.status.success(), - "Benchmark command failed:\nstderr: {}", - String::from_utf8_lossy(&output.stderr) - ); - }, - criterion::BatchSize::PerIteration, - ); - } else { - b.iter(|| { - let output = make_cmd().output().unwrap(); - assert!( - output.status.success(), - "Benchmark command failed:\nstderr: {}", - String::from_utf8_lossy(&output.stderr) - ); - }); - } + // Cold matters here: the picker writes to + // `.git/wt/cache/picker-preview/` (Log / BranchDiff / + // UpstreamDiff entries), so without invalidation iter 1 + // measures real cost and iter 2+ measure cache hits. + bench_wt(b, &repo_path, *cold, make_cmd); }, ); } diff --git a/benches/remove.rs b/benches/remove.rs index 0a19d910b..3af8fb897 100644 --- a/benches/remove.rs +++ b/benches/remove.rs @@ -1,12 +1,12 @@ // Benchmarks for `wt remove` end-to-end performance // -// Measures the full remove command including output rendering and hook spawning, -// to complement `time_to_first_output` which exits before output. +// Measures the full remove command including output rendering and hook +// spawning, to complement `first_output/remove` in `time_to_first_output`, +// which exits before output. // // Benchmark variants: // - remove_e2e/no_hooks — remove with --no-hooks (no hook loading) // - remove_e2e/with_hooks — remove with hooks configured (user + project) -// - remove_e2e/first_output — baseline: exits before output (same as time_to_first_output) // // Run examples: // cargo bench --bench remove # All variants @@ -16,7 +16,7 @@ use criterion::{Criterion, criterion_group, criterion_main}; use std::path::{Path, PathBuf}; use std::process::Command; use worktrunk::testing::isolate_subprocess_env; -use wt_perf::{RepoConfig, invalidate_caches_auto, run_git, run_git_ok, setup_fake_remote}; +use wt_perf::{RepoConfig, run_git, run_git_ok, setup_fake_remote}; /// Create a benchmark repo at a specific path with optional hooks. fn create_bench_repo(base_path: &Path, with_hooks: bool) -> PathBuf { @@ -109,35 +109,6 @@ fn bench_remove_e2e(c: &mut Criterion) { )) }; - // Baseline: first_output (exits before output rendering). - // - // Invalidates caches per iteration so the timing reflects first-invocation - // TTFO — `prepare_worktree_removal` writes to `.git/wt/cache/` via - // `compute_integration_lazy`, and reusing it across iterations would - // measure warm-cache cost instead. `BatchSize::PerIteration` (not - // `SmallInput`) so the setup actually runs before every measured iter — - // under `SmallInput`, criterion calls `setup` once per batch and runs - // the timed routines back-to-back, leaving only iter 1 cold per batch. - group.bench_function("first_output", |b| { - b.iter_batched( - || invalidate_caches_auto(&repo_no_hooks), - |_| { - let mut cmd = Command::new(binary); - cmd.args(["remove", "--yes", "--no-hooks", "--force", "feature-wt-1"]); - cmd.current_dir(&repo_no_hooks); - isolate_subprocess_env(&mut cmd, Some(&user_config_no_hooks)); - cmd.env("WORKTRUNK_FIRST_OUTPUT", "1"); - let output = cmd.output().unwrap(); - assert!( - output.status.success(), - "first_output failed: {}", - String::from_utf8_lossy(&output.stderr) - ); - }, - criterion::BatchSize::PerIteration, - ); - }); - // No hooks: --no-hooks (skip hook loading), run from feature worktree group.bench_function("no_hooks", |b| { b.iter_batched( diff --git a/benches/time_to_first_output.rs b/benches/time_to_first_output.rs index 16fec8f23..e0e1036cc 100644 --- a/benches/time_to_first_output.rs +++ b/benches/time_to_first_output.rs @@ -17,7 +17,7 @@ use criterion::{Criterion, criterion_group, criterion_main}; use std::path::Path; use std::process::Command; use worktrunk::testing::isolate_subprocess_env; -use wt_perf::{RepoConfig, create_repo, invalidate_caches_auto, setup_fake_remote}; +use wt_perf::{RepoConfig, bench_wt, create_repo, setup_fake_remote}; fn bench_first_output(c: &mut Criterion) { let mut group = c.benchmark_group("first_output"); @@ -38,45 +38,21 @@ fn bench_first_output(c: &mut Criterion) { // remove: exits after validation, before approval/output. // - // `prepare_worktree_removal` calls `compute_integration_lazy`, which - // populates `.git/wt/cache/{is-ancestor,has-added-changes,merge-add-probe}` - // on the first invocation. Without invalidation between iterations, iter 1 - // is cold and iter 2+ read from cache — the reported timing would be warm - // cache, which doesn't reflect the first-invocation TTFO a user sees. - // Invalidate via `iter_batched` so every iteration starts cold; use - // `BatchSize::PerIteration` (not `SmallInput`) so setup runs immediately - // before every measured iter — under `SmallInput`, criterion would run - // setup once per batch and time the routines back-to-back, leaving only - // iter 1 actually cold per batch. + // Cold matters here: `prepare_worktree_removal` calls + // `compute_integration_lazy`, which populates + // `.git/wt/cache/{is-ancestor,has-added-changes,merge-add-probe}` on the + // first invocation. Without per-iteration invalidation the reported + // timing would be warm cache, not the first-invocation TTFO a user sees. group.bench_function("remove", |b| { - b.iter_batched( - || invalidate_caches_auto(&repo_path), - |_| { - let output = - make_cmd(&["remove", "--yes", "--no-hooks", "--force", "feature-wt-1"]) - .output() - .unwrap(); - assert!( - output.status.success(), - "Benchmark command failed:\nstderr: {}", - String::from_utf8_lossy(&output.stderr) - ); - }, - criterion::BatchSize::PerIteration, - ); + bench_wt(b, &repo_path, true, || { + make_cmd(&["remove", "--yes", "--no-hooks", "--force", "feature-wt-1"]) + }); }); // switch: exits after execute_switch, before mismatch computation and output group.bench_function("switch", |b| { - b.iter(|| { - let output = make_cmd(&["switch", "--yes", "--no-hooks", "feature-wt-1"]) - .output() - .unwrap(); - assert!( - output.status.success(), - "Benchmark command failed:\nstderr: {}", - String::from_utf8_lossy(&output.stderr) - ); + bench_wt(b, &repo_path, false, || { + make_cmd(&["switch", "--yes", "--no-hooks", "feature-wt-1"]) }); }); diff --git a/src/cli/config.rs b/src/cli/config.rs index fa471bb2e..e049610b5 100644 --- a/src/cli/config.rs +++ b/src/cli/config.rs @@ -1333,9 +1333,7 @@ $ wt config state logs --format=json | jq '.hook_output[] | select(.branch | sta #[command( after_long_help = r#"Summarize where a single `wt` invocation spent its time, reading the records captured to `trace.jsonl` by a `-vv` run. -Reads `.git/wt/logs/trace.jsonl` by default, or a trace given as an argument (e.g. a CI artifact, or `-` for stdin). The report answers three questions: where time goes (subprocess time by command type, plus the slowest individual jobs), how parallel the run was (concurrency factor and peak concurrency), and where work was wasted (commands re-run with the same context). For a `wt list` capture it also shows derived latencies (time to skeleton, time to first result) and a timeline of collect milestones; the skeleton/first-result markers need a terminal (TTY) capture. `--format=json` emits the same data for scripting. - -For an interactive timeline or a Perfetto trace, use the `wt-perf` helper (`cargo run -p wt-perf -- timeline`); both read the same `trace.jsonl`. +Reads `.git/wt/logs/trace.jsonl` by default, or a trace given as an argument (e.g. a CI artifact, or `-` for stdin). The report answers three questions: where time goes (subprocess time by command type and by worktree, plus the slowest individual jobs), how parallel the run was (concurrency factor and peak concurrency), and where work was wasted (commands re-run with the same context). For a `wt list` capture it also shows derived latencies (time to skeleton, time to first result) and a timeline of collect milestones; the skeleton/first-result markers need a terminal (TTY) capture. `--format=json` emits the same data for scripting. ## Examples diff --git a/src/testing/mod.rs b/src/testing/mod.rs index e165b8a0c..35f84e869 100644 --- a/src/testing/mod.rs +++ b/src/testing/mod.rs @@ -60,11 +60,11 @@ pub fn wt_bin() -> PathBuf { ) } -/// Path to a workspace member binary (e.g., `wt-perf`, `mock-stub`). +/// Path to a workspace member binary (`mock-stub`). /// -/// These are binaries from other workspace packages (not the main `wt` crate), -/// so `CARGO_BIN_EXE_` isn't available. Derives the path from the test -/// executable's location in `target/debug/deps/`. +/// Binaries from other workspace packages (not the main `wt` crate) have no +/// `CARGO_BIN_EXE_` in the main crate's tests. Derives the path from +/// the test executable's location in `target/debug/deps/`. pub fn workspace_bin(name: &str) -> PathBuf { let mut path = std::env::current_exe().expect("failed to get test executable path"); path.pop(); // Remove test binary name diff --git a/src/trace/mod.rs b/src/trace/mod.rs index d3543694c..5dac0787a 100644 --- a/src/trace/mod.rs +++ b/src/trace/mod.rs @@ -41,9 +41,11 @@ pub mod chrome; pub mod emit; pub mod parse; pub mod profile; +pub mod timeline; // Re-export main types for convenience pub use chrome::to_chrome_trace; pub use emit::{CommandTrace, Span, WT_TRACE_TARGET, instant, now_us, thread_id}; pub use parse::{TraceEntry, TraceEntryKind, TraceResult, parse_lines}; pub use profile::{CacheReport, Profile}; +pub use timeline::render_timeline; diff --git a/src/trace/profile.rs b/src/trace/profile.rs index 9abed8612..adfa74c3c 100644 --- a/src/trace/profile.rs +++ b/src/trace/profile.rs @@ -7,7 +7,9 @@ //! //! - **Where does time go?** — [`Profile::by_type`] groups subprocesses by command //! shape (`git status`, `git rev-list`, `gh pr list`) with count/total/max/avg, -//! and [`Profile::slowest`] lists the most expensive individual jobs. +//! [`Profile::by_context`] groups them by context (typically worktree name) to +//! localize which worktree the parallel phase spends its time on, and +//! [`Profile::slowest`] lists the most expensive individual jobs. //! - **How parallel are we?** — [`Profile::parallelism`] is Σ(subprocess time) ÷ //! their wall span; [`Profile::peak_concurrency`] is the most subprocesses in //! flight at once. @@ -18,10 +20,10 @@ //! //! The analysis ([`Profile::from_entries`], [`CacheReport::from_entries`]) is pure //! data over `&[TraceEntry]` and carries no styling, so it compiles without the -//! `cli` feature and is shared by both `wt config state logs profile` (which -//! renders via [`Profile::render_text`] or serializes the struct for `--format=json`) -//! and the `wt-perf` helper (which reuses [`CacheReport`] for its `cache-check` -//! output). The struct's `Serialize` impl is the single canonical JSON source. +//! `cli` feature and is shared by `wt config state logs profile` (which renders +//! via [`Profile::render_text`] or serializes the struct for `--format=json`) and +//! `wt diagnose` (which embeds the rendered text). The struct's `Serialize` impl +//! is the single canonical JSON source. //! //! [`benches/CLAUDE.md`]: ../../../benches/CLAUDE.md @@ -100,6 +102,9 @@ pub struct Profile { pub key_intervals: KeyIntervals, /// Subprocess time grouped by command shape, busiest first. pub by_type: Vec, + /// Subprocess time grouped by context (typically worktree name), busiest + /// first. Commands with no context land in a `(none)` bucket. + pub by_context: Vec, /// The most expensive individual jobs (commands and spans), slowest first. pub slowest: Vec, /// Redundant same-context commands. @@ -160,6 +165,15 @@ pub struct TypeStat { pub avg: Duration, } +/// Aggregated subprocess timing for one context (typically a worktree name). +#[derive(Debug, Clone, PartialEq, Serialize)] +pub struct ContextStat { + pub context: String, + pub count: usize, + #[serde(rename = "total_us", serialize_with = "ser_dur_us")] + pub total: Duration, +} + /// One expensive job in [`Profile::slowest`]. #[derive(Debug, Clone, PartialEq, Serialize)] pub struct Slow { @@ -285,8 +299,9 @@ fn command_type(command: &str) -> String { parts.join(" ") } -/// Display label for one slowest-list command. -fn command_label(command: &str, context: Option<&str>, result: &TraceResult) -> String { +/// Display label for a command: `cmd [context]` plus a failure marker. Shared +/// with the timeline renderer so the two views can't drift. +pub(super) fn command_label(command: &str, context: Option<&str>, result: &TraceResult) -> String { let mut label = match context { Some(c) => format!("{command} [{c}]"), None => command.to_string(), @@ -326,6 +341,7 @@ impl Profile { let mut command_total_us = 0u64; let mut span_total_us = 0u64; let mut by_type_map: BTreeMap = BTreeMap::new(); + let mut by_context_map: BTreeMap<&str, (usize, u64)> = BTreeMap::new(); let mut threads: HashSet = HashSet::new(); // (start, end) for timed subprocesses — drives parallelism & peak concurrency. let mut intervals: Vec<(u64, u64)> = Vec::new(); @@ -346,6 +362,11 @@ impl Profile { stat.0 += 1; stat.1 += dur_us; stat.2 = stat.2.max(dur_us); + let ctx_stat = by_context_map + .entry(entry.context.as_deref().unwrap_or("(none)")) + .or_default(); + ctx_stat.0 += 1; + ctx_stat.1 += dur_us; if let Some(tid) = entry.thread_id { threads.insert(tid); } @@ -380,6 +401,20 @@ impl Profile { .collect(); by_type.sort_by(|a, b| b.total.cmp(&a.total).then_with(|| a.key.cmp(&b.key))); + let mut by_context: Vec = by_context_map + .into_iter() + .map(|(context, (count, total))| ContextStat { + context: context.to_string(), + count, + total: Duration::from_micros(total), + }) + .collect(); + by_context.sort_by(|a, b| { + b.total + .cmp(&a.total) + .then_with(|| a.context.cmp(&b.context)) + }); + slowest.sort_by_key(|s| std::cmp::Reverse(s.duration)); slowest.truncate(SLOWEST_LIMIT); @@ -435,6 +470,7 @@ impl Profile { thread_count: threads.len(), key_intervals, by_type, + by_context, slowest, cache: CacheReport::from_entries(entries), phases, @@ -525,6 +561,30 @@ impl Profile { )); } + // A single bucket would restate the summary line's totals, so the + // per-context attribution table only renders when it can attribute. + if self.by_context.len() > 1 { + out.push('\n'); + out.push_str(&format_heading("BY CONTEXT", None)); + out.push('\n'); + let mut rows = vec![vec![ + "context".to_string(), + "count".to_string(), + "total".to_string(), + ]]; + for stat in &self.by_context { + rows.push(vec![ + stat.context.clone(), + stat.count.to_string(), + fmt_dur(stat.total), + ]); + } + out.push_str(&render_table( + &rows, + &[Align::Left, Align::Right, Align::Right], + )); + } + if !self.slowest.is_empty() { out.push('\n'); out.push_str(&format_heading("SLOWEST CALLS", None)); @@ -766,7 +826,7 @@ fn concurrency(intervals: &[(u64, u64)]) -> (Option, Option) { } #[derive(Clone, Copy)] -enum Align { +pub(super) enum Align { Left, Right, } @@ -780,7 +840,7 @@ enum Align { /// Durations all render in one unit ([`fmt_dur`]) with two decimals, so /// right-aligning a duration column lines up both the decimal points and the /// `ms` suffix — no decimal-specific alignment is needed. -fn render_table(rows: &[Vec], aligns: &[Align]) -> String { +pub(super) fn render_table(rows: &[Vec], aligns: &[Align]) -> String { let cols = aligns.len(); let mut widths = vec![0usize; cols]; for row in rows { @@ -820,7 +880,7 @@ fn render_table(rows: &[Vec], aligns: &[Align]) -> String { /// Format a duration in milliseconds with two decimals — one unit everywhere so /// every duration column aligns (decimals and the `ms` suffix line up under /// right-alignment) regardless of magnitude. -fn fmt_dur(d: Duration) -> String { +pub(super) fn fmt_dur(d: Duration) -> String { format!("{:.2}ms", d.as_micros() as f64 / 1_000.0) } @@ -1094,6 +1154,13 @@ mod tests { "avg_us": 4500 } ], + "by_context": [ + { + "context": "main", + "count": 2, + "total_us": 9000 + } + ], "slowest": [ { "dur_us": 5000, diff --git a/src/trace/snapshots/worktrunk__trace__profile__tests__renders_full_report.snap b/src/trace/snapshots/worktrunk__trace__profile__tests__renders_full_report.snap index dff328976..78ee9ac9b 100644 --- a/src/trace/snapshots/worktrunk__trace__profile__tests__renders_full_report.snap +++ b/src/trace/snapshots/worktrunk__trace__profile__tests__renders_full_report.snap @@ -11,6 +11,11 @@ BY COMMAND TYPE git config 2 7.00ms 4.00ms 3.50ms git diff 1 5.00ms 5.00ms 5.00ms +BY CONTEXT + context count total + main 4 24.00ms + feature 1 8.00ms + SLOWEST CALLS 12.00ms git status --porcelain [main] 8.00ms git status --porcelain [feature] diff --git a/src/trace/snapshots/worktrunk__trace__profile__tests__truncates_slowest_and_collapses_cache.snap b/src/trace/snapshots/worktrunk__trace__profile__tests__truncates_slowest_and_collapses_cache.snap index b53da56f9..6fe5bf1be 100644 --- a/src/trace/snapshots/worktrunk__trace__profile__tests__truncates_slowest_and_collapses_cache.snap +++ b/src/trace/snapshots/worktrunk__trace__profile__tests__truncates_slowest_and_collapses_cache.snap @@ -10,6 +10,11 @@ BY COMMAND TYPE git 48 1845.60ms 50.00ms 38.45ms git xctx 4 6.30ms 2.00ms 1.57ms +BY CONTEXT + context count total + w1 50 1849.40ms + w2 2 2.50ms + SLOWEST CALLS 50.00ms git cmd00 [w1] 49.90ms git cmd00 [w1] diff --git a/src/trace/timeline.rs b/src/trace/timeline.rs new file mode 100644 index 000000000..ec782add2 --- /dev/null +++ b/src/trace/timeline.rs @@ -0,0 +1,215 @@ +//! Render trace entries as a start-time-sorted text timeline. +//! +//! The per-record view of a single `wt` invocation: one row per +//! command/span/instant in start order, then a summary of subprocess totals, +//! the traced span, and the externally measured wall. Complements +//! [`Profile`](super::Profile), the aggregate view over the same records; +//! `wt-perf timeline` is the consumer, and supplies `wall` from its own +//! spawn → wait measurement (the trace can't see the process prelude — argv +//! parsing, dyld, code before `init_logging` sets the trace epoch — or the +//! exit path, so the gap between `traced` and `wall` is the unobserved +//! overhead). Labels and tables come from the same helpers as +//! [`Profile::render_text`](super::Profile::render_text), so the two views +//! can't drift. + +use std::time::Duration; + +use super::parse::{TraceEntry, TraceEntryKind}; +use super::profile::{Align, command_label, fmt_dur, render_table}; + +/// Duration of an entry (zero for instant events). +fn duration_of(e: &TraceEntry) -> Duration { + match &e.kind { + TraceEntryKind::Command { duration, .. } | TraceEntryKind::Span { duration, .. } => { + *duration + } + TraceEntryKind::Instant { .. } => Duration::ZERO, + } +} + +/// Render parsed entries as a column-aligned, start-time-sorted timeline. +pub fn render_timeline(entries: &[TraceEntry], wall: Duration) -> String { + let mut sorted: Vec<&TraceEntry> = entries.iter().collect(); + sorted.sort_by_key(|e| e.start_time_us.unwrap_or(0)); + + let mut rows = vec![ + ["ts(ms)", "dur", "tid", "kind", "name"] + .map(str::to_string) + .to_vec(), + ]; + for e in &sorted { + let (kind, dur, name) = match &e.kind { + TraceEntryKind::Command { + command, + duration, + result, + .. + } => ( + "cmd", + fmt_dur(*duration), + command_label(command, e.context.as_deref(), result), + ), + TraceEntryKind::Span { name, duration } => ("span", fmt_dur(*duration), name.clone()), + TraceEntryKind::Instant { name } => ("event", String::new(), name.clone()), + }; + rows.push(vec![ + format!("{:.3}", e.start_time_us.unwrap_or(0) as f64 / 1_000.0), + dur, + e.thread_id + .map(|t| t.to_string()) + .unwrap_or_else(|| "-".into()), + kind.to_string(), + name, + ]); + } + let mut out = render_table( + &rows, + &[ + Align::Right, + Align::Right, + Align::Right, + Align::Left, + Align::Left, + ], + ); + + // Summary: subprocess totals + traced span + true process wall. + let cmds: Vec<(Duration, String)> = sorted + .iter() + .filter_map(|e| match &e.kind { + TraceEntryKind::Command { + command, + duration, + result, + .. + } => Some(( + *duration, + command_label(command, e.context.as_deref(), result), + )), + _ => None, + }) + .collect(); + let cmd_total: Duration = cmds.iter().map(|(d, _)| *d).sum(); + let slowest = cmds.iter().max_by_key(|(d, _)| *d); + let traced = Duration::from_micros( + sorted + .iter() + .map(|e| e.start_time_us.unwrap_or(0) + duration_of(e).as_micros() as u64) + .max() + .unwrap_or(0) + .saturating_sub( + sorted + .iter() + .map(|e| e.start_time_us.unwrap_or(0)) + .min() + .unwrap_or(0), + ), + ); + let untraced = wall.saturating_sub(traced); + + out.push('\n'); + if let Some((dur, name)) = slowest { + let plural = if cmds.len() == 1 { "" } else { "es" }; + out.push_str(&format!( + "{} subprocess{plural} totaling {} (slowest: {} {name})\n", + cmds.len(), + fmt_dur(cmd_total), + fmt_dur(*dur), + )); + } else { + out.push_str("0 subprocesses\n"); + } + out.push_str(&format!( + "traced: {} (first → last record)\n", + fmt_dur(traced) + )); + out.push_str(&format!( + "wall: {} (spawn → wait; +{} untraced prelude/epilogue)\n", + fmt_dur(wall), + fmt_dur(untraced), + )); + out +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::trace::TraceResult; + + fn span(name: &str, ts_us: u64, dur_us: u64, tid: u64) -> TraceEntry { + TraceEntry { + context: None, + kind: TraceEntryKind::Span { + name: name.to_string(), + duration: Duration::from_micros(dur_us), + }, + start_time_us: Some(ts_us), + thread_id: Some(tid), + } + } + + fn cmd( + cmd: &str, + ctx: Option<&str>, + ts_us: u64, + dur_us: u64, + tid: u64, + ok: bool, + ) -> TraceEntry { + TraceEntry { + context: ctx.map(|s| s.to_string()), + kind: TraceEntryKind::Command { + command: cmd.to_string(), + duration: Duration::from_micros(dur_us), + result: TraceResult::Completed { success: ok }, + reads_stdin: false, + }, + start_time_us: Some(ts_us), + thread_id: Some(tid), + } + } + + #[test] + fn renders_sorted_timeline_with_summary() { + // Emit order swaps span and child cmd (parent finishes after child), + // so this exercises the sort-by-start-time guarantee. + let entries = vec![ + cmd("git rev-parse HEAD", Some("repo"), 50, 4_000, 1, true), + span("prewarm", 30, 4_100, 1), + span("init_logging", 0, 8, 1), + span("user_config_load", 4_200, 280, 38), + ]; + // Wall = 6ms; traced = 4.48ms (4.2ms start → 4.48ms end); + // untraced prelude/epilogue = 6 - 4.48 = 1.52ms. + insta::assert_snapshot!( + render_timeline(&entries, Duration::from_micros(6_000)), + @" + ts(ms) dur tid kind name + 0.000 0.01ms 1 span init_logging + 0.030 4.10ms 1 span prewarm + 0.050 4.00ms 1 cmd git rev-parse HEAD [repo] + 4.200 0.28ms 38 span user_config_load + + 1 subprocess totaling 4.00ms (slowest: 4.00ms git rev-parse HEAD [repo]) + traced: 4.48ms (first → last record) + wall: 6.00ms (spawn → wait; +1.52ms untraced prelude/epilogue) + " + ); + } + + #[test] + fn cmd_failure_annotates_name() { + let entries = vec![cmd("git foo", None, 0, 1_000, 1, false)]; + insta::assert_snapshot!( + render_timeline(&entries, Duration::from_millis(2)), + @" + ts(ms) dur tid kind name + 0.000 1.00ms 1 cmd git foo (ok=false) + + 1 subprocess totaling 1.00ms (slowest: 1.00ms git foo (ok=false)) + traced: 1.00ms (first → last record) + wall: 2.00ms (spawn → wait; +1.00ms untraced prelude/epilogue) + " + ); + } +} diff --git a/tests/helpers/wt-perf/Cargo.toml b/tests/helpers/wt-perf/Cargo.toml index 558aa3c59..c9552b178 100644 --- a/tests/helpers/wt-perf/Cargo.toml +++ b/tests/helpers/wt-perf/Cargo.toml @@ -1,7 +1,8 @@ # HOW THE BINARY GETS BUILT: -# Has a dummy integration test (tests/builds.rs) that triggers binary compilation -# when running `cargo test`. Combined with `workspace.default-members` including -# this package, `cargo test` automatically builds the binary. +# The CLI integration tests in tests/cli.rs are in-package, so cargo builds +# the wt-perf binary to run them (and sets CARGO_BIN_EXE_wt-perf). Combined +# with `workspace.default-members` including this package, a workspace +# `cargo test` builds and tests the binary automatically. [package] name = "wt-perf" version = "0.1.0" @@ -18,11 +19,8 @@ dunce = "1" # For CLI clap = { version = "4.6", features = ["derive"] } -# For JSON output -serde_json = "1.0.145" - -# For column-aligned timeline tables (elastic tabstops) -tabwriter = "1" +# For the shared warm/cold bench runner (bench_wt) +criterion = "0.8" # For trace parsing (reuse worktrunk's trace module). # `default-features = false` avoids leaking the `cli` feature into the @@ -32,7 +30,7 @@ tabwriter = "1" worktrunk = { path = "../../..", default-features = false } [dev-dependencies] -insta = "1.47.2" +serde_json = "1.0.145" [lib] name = "wt_perf" diff --git a/tests/helpers/wt-perf/src/lib.rs b/tests/helpers/wt-perf/src/lib.rs index afc86e1f7..cd94a094c 100644 --- a/tests/helpers/wt-perf/src/lib.rs +++ b/tests/helpers/wt-perf/src/lib.rs @@ -108,6 +108,35 @@ impl RepoConfig { } } +/// A parsed `wt-perf setup` config string. +/// +/// Most configs map onto the flat [`RepoConfig`] (every worktree/branch +/// identical); `mixed-W-B` builds the varied-state fixture via +/// [`create_mixed_repo_at`] instead. +pub enum SetupConfig { + Flat(RepoConfig), + Mixed { worktrees: usize, branches: usize }, +} + +impl SetupConfig { + /// Create the repo at `base_path`; returns `(worktrees, branches)`. + pub fn create_at(&self, base_path: &Path) -> (usize, usize) { + match self { + SetupConfig::Flat(cfg) => { + create_repo_at(cfg, base_path); + (cfg.worktrees, cfg.branches) + } + SetupConfig::Mixed { + worktrees, + branches, + } => { + create_mixed_repo_at(*worktrees, *branches, base_path); + (*worktrees, *branches) + } + } + } +} + /// Build a `git` command isolated from host context, with config /// redirected to `NULL_DEVICE`. Thin call-site wrapper around /// [`configure_git_cmd`] — every git invocation in this crate goes @@ -119,6 +148,53 @@ fn git_command() -> Command { cmd } +/// Run a `wt` benchmark iteration function under criterion, warm or cold. +/// +/// The one place the warm/cold iteration strategy lives: warm uses plain +/// `Bencher::iter` (persistent caches stay hot across iterations); cold +/// invalidates the repo's caches immediately before every measured iteration. +/// +/// Cold uses `iter_batched` with `BatchSize::PerIteration`, not `SmallInput`: +/// under `SmallInput`, criterion calls the setup once for an entire batch up +/// front and then times the routines back-to-back, so only the first run per +/// batch is actually cold — the rest hit a `.git/wt/cache/` the previous run +/// just repopulated, biasing the "cold" median warm. `PerIteration` runs +/// setup → time(routine) per iteration, so every measured run is genuinely +/// cold; the invalidation is far cheaper than a `wt` subprocess, so the +/// per-iteration `Instant::now` overhead doesn't dominate. When this fix +/// landed, cold variance tightened (e.g. `first_output/remove` spread +/// 2.4ms → 0.65ms) and medians rose to their true cold cost. +/// +/// `make_cmd` builds a fresh command per iteration; the child's exit status is +/// asserted so a benchmark can't silently time a failing command. +pub fn bench_wt( + b: &mut criterion::Bencher, + repo_path: &Path, + cold: bool, + mut make_cmd: impl FnMut() -> Command, +) { + let mut run = move || run_and_check(&mut make_cmd()); + if cold { + b.iter_batched( + || invalidate_caches_auto(repo_path), + |_| run(), + criterion::BatchSize::PerIteration, + ); + } else { + b.iter(run); + } +} + +/// Spawn the command, wait, and panic with its stderr if it failed. +pub fn run_and_check(cmd: &mut Command) { + let output = cmd.output().unwrap(); + assert!( + output.status.success(), + "benchmark command failed:\nstderr: {}", + String::from_utf8_lossy(&output.stderr) + ); +} + /// Run a git command in the given directory. Panics on failure. pub fn run_git(path: &Path, args: &[&str]) { let output = git_command().args(args).current_dir(path).output().unwrap(); @@ -141,6 +217,28 @@ pub fn run_git_ok(path: &Path, args: &[&str]) -> bool { .is_ok_and(|o| o.status.success()) } +/// `git init` a fixture repo at `repo_path` (creating the directory) with the +/// benchmark identity and all background auto-maintenance disabled. +/// +/// Auto-maintenance must be off: rapid commits in a fixture build loop +/// trigger detached `git gc` / `git maintenance` runs whose pack-and-prune +/// steps race the foreground `git add` / `git commit`, producing intermittent +/// "invalid object ..." / "unable to create temporary file" / "failed to +/// insert into database" failures partway through a 500-commit fixture. +/// Modern git enables both `gc.auto` (loose-object threshold) and +/// `maintenance.auto` (the post-command hook scheduler) by default, so both +/// are silenced. Fixture builders run an explicit `git gc` once at the end +/// instead, for a mature-repo shape. +fn init_bench_repo(repo_path: &Path) { + std::fs::create_dir_all(repo_path).unwrap(); + run_git(repo_path, &["init", "-b", "main"]); + run_git(repo_path, &["config", "user.name", "Benchmark"]); + run_git(repo_path, &["config", "user.email", "bench@test.com"]); + run_git(repo_path, &["config", "gc.auto", "0"]); + run_git(repo_path, &["config", "gc.autoPackLimit", "0"]); + run_git(repo_path, &["config", "maintenance.auto", "false"]); +} + /// Create a test repository from config. /// /// Returns a `TempDir` containing the repo. The main worktree is at `temp.path().join("repo")`. @@ -158,23 +256,7 @@ pub fn create_repo(config: &RepoConfig) -> TempDir { /// - Feature worktrees: `base_path.feature-wt-N` (siblings in parent directory) pub fn create_repo_at(config: &RepoConfig, base_path: &Path) { let repo_path = base_path.to_path_buf(); - std::fs::create_dir_all(&repo_path).unwrap(); - - run_git(&repo_path, &["init", "-b", "main"]); - run_git(&repo_path, &["config", "user.name", "Benchmark"]); - run_git(&repo_path, &["config", "user.email", "bench@test.com"]); - // Disable all background auto-maintenance: rapid commits in the - // build loop trigger detached `git gc` / `git maintenance` runs - // whose pack-and-prune steps race the foreground `git add` / - // `git commit`, producing intermittent "invalid object ..." / - // "unable to create temporary file" / "failed to insert into - // database" failures partway through a 500-commit fixture. Modern - // git enables both `gc.auto` (loose-object threshold) and - // `maintenance.auto` (the post-command hook scheduler) by default, - // so we have to silence both. - run_git(&repo_path, &["config", "gc.auto", "0"]); - run_git(&repo_path, &["config", "gc.autoPackLimit", "0"]); - run_git(&repo_path, &["config", "maintenance.auto", "false"]); + init_bench_repo(&repo_path); // Create initial file structure let num_files = config.files.max(1); @@ -614,15 +696,7 @@ pub fn create_mixed_repo_at(worktrees: usize, branches: usize, repo: &Path) { const CHECKPOINT_EVERY: usize = 5; let repo = repo.to_path_buf(); - std::fs::create_dir_all(&repo).unwrap(); - - run_git(&repo, &["init", "-b", "main"]); - run_git(&repo, &["config", "user.name", "Benchmark"]); - run_git(&repo, &["config", "user.email", "bench@test.com"]); - // Disable background auto-maintenance (see create_repo_at for why). - run_git(&repo, &["config", "gc.auto", "0"]); - run_git(&repo, &["config", "gc.autoPackLimit", "0"]); - run_git(&repo, &["config", "maintenance.auto", "false"]); + init_bench_repo(&repo); for i in 0..FILES { let p = repo.join(format!("src/file_{i}.rs")); @@ -751,39 +825,41 @@ pub fn canonicalize(path: &Path) -> std::io::Result { dunce::canonicalize(path) } -/// Parse a config string into a RepoConfig. +/// Parse a `wt-perf setup` config string. /// /// Supported formats: /// - `typical-N` - typical repo with N worktrees /// - `branches-N` - N branches with 1 commit each /// - `branches-N-M` - N branches with M commits each /// - `divergent` - many divergent branches (GH #461) +/// - `mixed-W-B` - W worktrees + B branches in varied states /// - `picker-test` - config for wt switch interactive picker testing -pub fn parse_config(s: &str) -> Option { +pub fn parse_config(s: &str) -> Option { if let Some(n) = s.strip_prefix("typical-") { let worktrees: usize = n.parse().ok()?; - return Some(RepoConfig::typical(worktrees)); + return Some(SetupConfig::Flat(RepoConfig::typical(worktrees))); } if let Some(rest) = s.strip_prefix("branches-") { - let parts: Vec<&str> = rest.split('-').collect(); - match parts.as_slice() { - [count] => { - let count: usize = count.parse().ok()?; - return Some(RepoConfig::branches(count, 1)); - } - [count, commits] => { - let count: usize = count.parse().ok()?; - let commits: usize = commits.parse().ok()?; - return Some(RepoConfig::branches(count, commits)); - } + let config = match rest.split('-').collect::>().as_slice() { + [count] => RepoConfig::branches(count.parse().ok()?, 1), + [count, commits] => RepoConfig::branches(count.parse().ok()?, commits.parse().ok()?), _ => return None, - } + }; + return Some(SetupConfig::Flat(config)); + } + + if let Some(rest) = s.strip_prefix("mixed-") { + let (w, b) = rest.split_once('-')?; + return Some(SetupConfig::Mixed { + worktrees: w.parse().ok()?, + branches: b.parse().ok()?, + }); } match s { - "divergent" => Some(RepoConfig::many_divergent_branches()), - "picker-test" => Some(RepoConfig::picker_test()), + "divergent" => Some(SetupConfig::Flat(RepoConfig::many_divergent_branches())), + "picker-test" => Some(SetupConfig::Flat(RepoConfig::picker_test())), _ => None, } } diff --git a/tests/helpers/wt-perf/src/main.rs b/tests/helpers/wt-perf/src/main.rs index be3510491..f19bcbbfb 100644 --- a/tests/helpers/wt-perf/src/main.rs +++ b/tests/helpers/wt-perf/src/main.rs @@ -8,10 +8,7 @@ use std::process::{Command, Stdio}; use std::time::{Duration, Instant}; use clap::{Parser, Subcommand}; -use worktrunk::trace::{TraceEntry, TraceEntryKind, TraceResult}; -use wt_perf::{ - canonicalize, create_mixed_repo_at, create_repo_at, invalidate_caches_auto, parse_config, -}; +use wt_perf::{canonicalize, invalidate_caches_auto, parse_config}; #[derive(Parser)] #[command(name = "wt-perf")] @@ -66,17 +63,6 @@ enum Commands { file: Option, }, - /// Analyze a trace.jsonl for duplicate commands (cache effectiveness) - #[command(after_long_help = r#"EXAMPLES: - # Check cache effectiveness for wt list - wt -vv list --progressive - wt-perf cache-check .git/wt/logs/trace.jsonl -"#)] - CacheCheck { - /// Path to a trace.jsonl file (reads from stdin if omitted) - file: Option, - }, - /// Run a `wt` command with tracing on and render a timeline. /// /// Runs the child with `-vv` so it writes `trace.jsonl`, reads that back, @@ -124,31 +110,20 @@ fn main() { path, persist, } => { - // `mixed-W-B`: W worktrees + B branches in varied states (warm - // re-run benchmark fixture); handled separately since it doesn't - // map onto the flat `RepoConfig`. - let mixed = parse_mixed(&config); - - let repo_config = if mixed.is_some() { - None - } else { - Some(parse_config(&config).unwrap_or_else(|| { - eprintln!("Unknown config: {}", config); - eprintln!(); - eprintln!("Available configs:"); - eprintln!( - " typical-N - Typical repo with N worktrees (500 commits, 100 files)" - ); - eprintln!(" branches-N - N branches with 1 commit each"); - eprintln!(" branches-N-M - N branches with M commits each"); - eprintln!(" divergent - 200 branches × 20 commits (GH #461 scenario)"); - eprintln!(" mixed-W-B - W worktrees + B branches in varied states"); - eprintln!( - " picker-test - Config for wt switch interactive picker testing" - ); - std::process::exit(1); - })) - }; + let spec = parse_config(&config).unwrap_or_else(|| { + eprintln!("Unknown config: {}", config); + eprintln!(); + eprintln!("Available configs:"); + eprintln!( + " typical-N - Typical repo with N worktrees (500 commits, 100 files)" + ); + eprintln!(" branches-N - N branches with 1 commit each"); + eprintln!(" branches-N-M - N branches with M commits each"); + eprintln!(" divergent - 200 branches × 20 commits (GH #461 scenario)"); + eprintln!(" mixed-W-B - W worktrees + B branches in varied states"); + eprintln!(" picker-test - Config for wt switch interactive picker testing"); + std::process::exit(1); + }); let base_path = if let Some(p) = path { std::fs::create_dir_all(&p).unwrap(); @@ -163,17 +138,7 @@ fn main() { }; eprintln!("Creating {} repo...", config); - let (worktrees, branches) = match (mixed, &repo_config) { - (Some((w, b)), _) => { - create_mixed_repo_at(w, b, &base_path); - (w, b) - } - (None, Some(cfg)) => { - create_repo_at(cfg, &base_path); - (cfg.worktrees, cfg.branches) - } - (None, None) => unreachable!("repo_config is Some when mixed is None"), - }; + let (worktrees, branches) = spec.create_at(&base_path); let mut parts = vec![format!("main @ {}", base_path.display())]; if worktrees > 1 { @@ -229,11 +194,6 @@ fn main() { println!("{}", worktrunk::trace::to_chrome_trace(&entries)); } - Commands::CacheCheck { file } => { - let entries = read_trace_entries(file.as_deref()); - cache_check(&entries); - } - Commands::Timeline { cold, repo, @@ -243,13 +203,6 @@ fn main() { } } -/// Parse a `mixed-W-B` config string into `(worktrees, branches)`. -fn parse_mixed(config: &str) -> Option<(usize, usize)> { - let rest = config.strip_prefix("mixed-")?; - let (w, b) = rest.split_once('-')?; - Some((w.parse().ok()?, b.parse().ok()?)) -} - /// Resolve the `wt` binary as a sibling of the current executable /// (`target/{debug,release}/wt-perf` → `target/{debug,release}/wt`). /// `EXE_SUFFIX` keeps this correct on Windows, where Cargo builds @@ -352,7 +305,7 @@ fn run_timeline(cold: bool, repo: Option, chrome: bool, wt_args: &[Stri if chrome { println!("{}", worktrunk::trace::to_chrome_trace(&entries)); } else { - print!("{}", render_timeline(&entries, wall)); + print!("{}", worktrunk::trace::render_timeline(&entries, wall)); } if !output.status.success() { @@ -402,119 +355,6 @@ fn trace_jsonl_path(dir: &std::path::Path) -> Option { Some(common.join("wt").join("logs").join("trace.jsonl")) } -/// Render parsed entries as a column-aligned, start-time-sorted timeline. -/// -/// `wall` is the externally-measured spawn → wait duration. The trace -/// can't see the prelude (argv parsing, dyld, time before `init_logging` -/// sets the trace epoch) or the exit path, so reporting `wall` lets -/// readers see how much of the process the trace actually accounts for — -/// the gap between `traced` and `wall` is the unobserved overhead. -/// -/// Column alignment uses `tabwriter`'s elastic tabstops (write `\t`-separated -/// rows, padding is computed at flush). Durations are rendered via -/// `Duration`'s `Debug` impl, which produces compact units (`999µs`, `4.5ms`, -/// `1.5s`) — matches what we want without a dedicated humanization crate. -fn render_timeline(entries: &[TraceEntry], wall: Duration) -> String { - let mut sorted: Vec<&TraceEntry> = entries.iter().collect(); - sorted.sort_by_key(|e| e.start_time_us.unwrap_or(0)); - - let mut tw = tabwriter::TabWriter::new(Vec::::new()) - .minwidth(2) - .padding(2); - writeln!(tw, "ts(ms)\tdur\ttid\tkind\tname").unwrap(); - for e in &sorted { - let (kind, dur, name) = describe(e); - let ts_ms = e.start_time_us.unwrap_or(0) as f64 / 1_000.0; - let tid = e - .thread_id - .map(|t| t.to_string()) - .unwrap_or_else(|| "-".into()); - writeln!(tw, "{ts_ms:.3}\t{dur:?}\t{tid}\t{kind}\t{name}").unwrap(); - } - tw.flush().unwrap(); - let mut out = String::from_utf8(tw.into_inner().unwrap()).unwrap(); - - // Summary: subprocess totals + traced span + true process wall. - let cmds: Vec<(Duration, String)> = sorted - .iter() - .filter_map(|e| match &e.kind { - TraceEntryKind::Command { duration, .. } => { - let (_, _, name) = describe(e); - Some((*duration, name)) - } - _ => None, - }) - .collect(); - let cmd_total: Duration = cmds.iter().map(|(d, _)| *d).sum(); - let slowest = cmds.iter().max_by_key(|(d, _)| *d); - let traced = Duration::from_micros( - sorted - .iter() - .map(|e| e.start_time_us.unwrap_or(0) + duration_of(e).as_micros() as u64) - .max() - .unwrap_or(0) - .saturating_sub( - sorted - .iter() - .map(|e| e.start_time_us.unwrap_or(0)) - .min() - .unwrap_or(0), - ), - ); - let untraced = wall.saturating_sub(traced); - - out.push('\n'); - if let Some((dur, name)) = slowest { - let plural = if cmds.len() == 1 { "" } else { "es" }; - out.push_str(&format!( - "{} subprocess{plural} totaling {cmd_total:?} (slowest: {dur:?} {name})\n", - cmds.len(), - )); - } else { - out.push_str("0 subprocesses\n"); - } - out.push_str(&format!("traced: {traced:?} (first → last record)\n")); - out.push_str(&format!( - "wall: {wall:?} (spawn → wait; +{untraced:?} untraced prelude/epilogue)\n" - )); - out -} - -/// Extract the (kind, duration, display-name) tuple for a trace entry. -fn describe(e: &TraceEntry) -> (&'static str, Duration, String) { - match &e.kind { - TraceEntryKind::Command { - command, - duration, - result, - .. - } => { - let mut label = match e.context.as_deref() { - Some(c) => format!("{command} [{c}]"), - None => command.clone(), - }; - match result { - TraceResult::Completed { success: false } => label.push_str(" (ok=false)"), - TraceResult::Error { message } => label.push_str(&format!(" (err: {message})")), - TraceResult::Completed { success: true } => {} - } - ("cmd", *duration, label) - } - TraceEntryKind::Span { name, duration } => ("span", *duration, name.clone()), - TraceEntryKind::Instant { name } => ("event", Duration::ZERO, name.clone()), - } -} - -/// Duration of an entry (zero for instant events). -fn duration_of(e: &TraceEntry) -> Duration { - match &e.kind { - TraceEntryKind::Command { duration, .. } | TraceEntryKind::Span { duration, .. } => { - *duration - } - TraceEntryKind::Instant { .. } => Duration::ZERO, - } -} - /// Read trace input from file or stdin, parse entries, and exit if empty. fn read_trace_entries(file: Option<&std::path::Path>) -> Vec { let input = match file { @@ -556,20 +396,6 @@ fn read_trace_entries(file: Option<&std::path::Path>) -> Vec TraceEntry { - TraceEntry { - context: None, - kind: TraceEntryKind::Span { - name: name.to_string(), - duration: Duration::from_micros(dur_us), - }, - start_time_us: Some(ts_us), - thread_id: Some(tid), - } - } - - fn cmd( - cmd: &str, - ctx: Option<&str>, - ts_us: u64, - dur_us: u64, - tid: u64, - ok: bool, - ) -> TraceEntry { - TraceEntry { - context: ctx.map(|s| s.to_string()), - kind: TraceEntryKind::Command { - command: cmd.to_string(), - duration: Duration::from_micros(dur_us), - result: TraceResult::Completed { success: ok }, - reads_stdin: false, - }, - start_time_us: Some(ts_us), - thread_id: Some(tid), - } - } - - #[test] - fn renders_sorted_timeline_with_summary() { - // Emit order swaps span and child cmd (parent finishes after child), - // so this exercises the sort-by-start-time guarantee. Durations are - // chosen so std `Duration` Debug renders compact (no trailing - // sub-millisecond precision): 4ms, 4.1ms, 280µs, 8µs. - let entries = vec![ - cmd("git rev-parse HEAD", Some("repo"), 50, 4_000, 1, true), - span("prewarm", 30, 4_100, 1), - span("init_logging", 0, 8, 1), - span("user_config_load", 4_200, 280, 38), - ]; - // Wall = 6ms; traced = 4.48ms (4.2ms start → 4.48ms end); - // untraced prelude/epilogue = 6 - 4.48 = ~1.52ms. - insta::assert_snapshot!( - render_timeline(&entries, Duration::from_micros(6_000)), - @r" - ts(ms) dur tid kind name - 0.000 8µs 1 span init_logging - 0.030 4.1ms 1 span prewarm - 0.050 4ms 1 cmd git rev-parse HEAD [repo] - 4.200 280µs 38 span user_config_load - - 1 subprocess totaling 4ms (slowest: 4ms git rev-parse HEAD [repo]) - traced: 4.48ms (first → last record) - wall: 6ms (spawn → wait; +1.52ms untraced prelude/epilogue) - " - ); - } - - #[test] - fn cmd_failure_annotates_name() { - let entries = vec![cmd("git foo", None, 0, 1_000, 1, false)]; - insta::assert_snapshot!( - render_timeline(&entries, Duration::from_millis(2)), - @r" - ts(ms) dur tid kind name - 0.000 1ms 1 cmd git foo (ok=false) - - 1 subprocess totaling 1ms (slowest: 1ms git foo (ok=false)) - traced: 1ms (first → last record) - wall: 2ms (spawn → wait; +1ms untraced prelude/epilogue) - " - ); - } } diff --git a/tests/helpers/wt-perf/tests/builds.rs b/tests/helpers/wt-perf/tests/builds.rs deleted file mode 100644 index d2afa2199..000000000 --- a/tests/helpers/wt-perf/tests/builds.rs +++ /dev/null @@ -1,5 +0,0 @@ -//! Dummy test that triggers binary compilation. -//! See wt-perf/Cargo.toml and mock-stub/Cargo.toml for why this is needed. - -#[test] -fn builds() {} diff --git a/tests/integration_tests/analyze_trace.rs b/tests/helpers/wt-perf/tests/cli.rs similarity index 94% rename from tests/integration_tests/analyze_trace.rs rename to tests/helpers/wt-perf/tests/cli.rs index 632043ace..a033d60af 100644 --- a/tests/integration_tests/analyze_trace.rs +++ b/tests/helpers/wt-perf/tests/cli.rs @@ -1,12 +1,14 @@ //! Integration tests for the wt-perf trace command. +//! +//! In-package so cargo builds the wt-perf binary to run them and provides its +//! path via `CARGO_BIN_EXE_wt-perf` — this is what triggers the binary build +//! under a workspace `cargo test` (see Cargo.toml's header comment). use std::io::Write; use std::process::{Command, Stdio}; -use crate::common::workspace_bin; - -fn wt_perf_bin() -> std::path::PathBuf { - workspace_bin("wt-perf") +fn wt_perf_bin() -> &'static str { + env!("CARGO_BIN_EXE_wt-perf") } /// Test that the binary produces Chrome Trace Format JSON for sample trace input. diff --git a/tests/integration_tests/config_state.rs b/tests/integration_tests/config_state.rs index e49b17ab0..b3a822512 100644 --- a/tests/integration_tests/config_state.rs +++ b/tests/integration_tests/config_state.rs @@ -417,6 +417,18 @@ fn test_logs_profile_json(repo: TestRepo) { "avg_us": 5000 } ], + "by_context": [ + { + "context": "main", + "count": 4, + "total_us": 24000 + }, + { + "context": "feature", + "count": 1, + "total_us": 8000 + } + ], "slowest": [ { "dur_us": 12000, diff --git a/tests/integration_tests/mod.rs b/tests/integration_tests/mod.rs index a79e27bed..36b7341a7 100644 --- a/tests/integration_tests/mod.rs +++ b/tests/integration_tests/mod.rs @@ -4,7 +4,6 @@ // // Windows path differences are handled by snapshot filters in setup_snapshot_settings(). -pub mod analyze_trace; pub mod approval_pty; pub mod approval_save; diff --git a/tests/snapshots/integration__integration_tests__config_state__logs_profile_from_stdin.snap b/tests/snapshots/integration__integration_tests__config_state__logs_profile_from_stdin.snap index 3c212e9a1..532d85479 100644 --- a/tests/snapshots/integration__integration_tests__config_state__logs_profile_from_stdin.snap +++ b/tests/snapshots/integration__integration_tests__config_state__logs_profile_from_stdin.snap @@ -11,6 +11,11 @@ expression: "String::from_utf8_lossy(&output.stdout)" git config 2 7.00ms 4.00ms 3.50ms git diff 1 5.00ms 5.00ms 5.00ms +BY CONTEXT + context count total + main 4 24.00ms + feature 1 8.00ms + SLOWEST CALLS 12.00ms git status --porcelain [main] 8.00ms git status --porcelain [feature] diff --git a/tests/snapshots/integration__integration_tests__help__help_config_state_logs_profile.snap b/tests/snapshots/integration__integration_tests__help__help_config_state_logs_profile.snap index 129e192ee..886de2ff9 100644 --- a/tests/snapshots/integration__integration_tests__help__help_config_state_logs_profile.snap +++ b/tests/snapshots/integration__integration_tests__help__help_config_state_logs_profile.snap @@ -69,10 +69,8 @@ Usage: wt config state logs profile [OPTIONS] [FILE] Summarize where a single wt invocation spent its time, reading the records captured to trace.jsonl by a -vv run. -Reads .git/wt/logs/trace.jsonl by default, or a trace given as an argument (e.g. a CI artifact, or - for stdin). The report answers three questions: where time goes (subprocess time by command type, plus the slowest individual jobs), how parallel the run was (concurrency factor and peak concurrency), and where work was wasted (commands re-run with the same context). For a wt list capture it also shows derived latencies (time to skeleton, time to first result) and a timeline of collect -milestones; the skeleton/first-result markers need a terminal (TTY) capture. --format=json emits the same data for scripting. - -For an interactive timeline or a Perfetto trace, use the wt-perf helper (cargo run -p wt-perf -- timeline); both read the same trace.jsonl. +Reads .git/wt/logs/trace.jsonl by default, or a trace given as an argument (e.g. a CI artifact, or - for stdin). The report answers three questions: where time goes (subprocess time by command type and by worktree, plus the slowest individual jobs), how parallel the run was (concurrency factor and peak concurrency), and where work was wasted (commands re-run with the same context). For a wt list capture it also shows derived latencies (time to skeleton, time to first result) and a timeline of +collect milestones; the skeleton/first-result markers need a terminal (TTY) capture. --format=json emits the same data for scripting. Examples From 8db54793a9826d9ea6c549a1d2c6c76074a439f7 Mon Sep 17 00:00:00 2001 From: Maximilian Roos Date: Thu, 9 Jul 2026 21:08:07 -0700 Subject: [PATCH 3/6] refactor(trace): fold in review findings on the perf consolidation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit From two review passes over the branch: - CacheReport shrinks to its same-context fields. The six dropped fields (total_commands, total_time, contexts, duplicated_commands, extra_calls, unique_commands) duplicated Profile fields or tallied cross-context repeats — expected fan-out noise the text report never showed. Their only external reader was wt-perf cache-check, deleted earlier on this branch. - src/trace/mod.rs docstring cut over to the module map + logs profile pointer; the trace_processor SQL examples it carried were retired from benches/CLAUDE.md earlier on this branch for the same reason. - Chrome args drop duration_ms (redundant with the native dur field). - render_table pads by display width (unicode-width, already a direct dep), replacing the ASCII-only invariant that the new BY CONTEXT table violated; CJK alignment test added. - Timeline instant-event row gains coverage (the one render path no test exercised); stale /main suffix fixed in benches/CLAUDE.md's invalidate example. Co-Authored-By: Claude Fable 5 --- benches/CLAUDE.md | 2 +- src/trace/chrome.rs | 12 +-- src/trace/mod.rs | 55 +++++--------- src/trace/profile.rs | 97 +++++++++---------------- src/trace/timeline.rs | 27 +++++-- tests/integration_tests/config_state.rs | 6 -- 6 files changed, 75 insertions(+), 124 deletions(-) diff --git a/benches/CLAUDE.md b/benches/CLAUDE.md index bf6af9654..02a0fc08f 100644 --- a/benches/CLAUDE.md +++ b/benches/CLAUDE.md @@ -175,7 +175,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 diff --git a/src/trace/chrome.rs b/src/trace/chrome.rs index 1494d48ed..c50acbf40 100644 --- a/src/trace/chrome.rs +++ b/src/trace/chrome.rs @@ -8,7 +8,7 @@ //! - **Complete events** (`ph: "X"`): Command executions and in-process spans, both with duration //! - **Instant events** (`ph: "I"`): Milestones without duration (e.g., "Showed skeleton") //! -//! See [`crate::trace`] for the capture pipeline and SQL query examples. +//! See [`crate::trace`] for the capture pipeline. //! //! # Format Reference //! @@ -58,9 +58,6 @@ struct TraceEventArgs { context: Option, /// Whether the command succeeded (always true for instant events) success: bool, - /// Duration in milliseconds (human-readable, only for command events) - #[serde(rename = "duration_ms", skip_serializing_if = "Option::is_none")] - duration_ms: Option, } /// The top-level Chrome Trace Format structure. @@ -119,7 +116,6 @@ pub fn to_chrome_trace(entries: &[TraceEntry]) -> String { args: Some(TraceEventArgs { context: entry.context.clone(), success: entry.is_success(), - duration_ms: Some(duration.as_secs_f64() * 1000.0), }), } } @@ -136,7 +132,6 @@ pub fn to_chrome_trace(entries: &[TraceEntry]) -> String { args: Some(TraceEventArgs { context: entry.context.clone(), success: true, - duration_ms: None, }), } } @@ -152,7 +147,6 @@ pub fn to_chrome_trace(entries: &[TraceEntry]) -> String { args: Some(TraceEventArgs { context: entry.context.clone(), success: true, - duration_ms: Some(duration.as_secs_f64() * 1000.0), }), }, } @@ -305,7 +299,6 @@ mod tests { assert_eq!(events[0]["args"]["context"], "feature"); assert_eq!(events[0]["args"]["success"], true); - assert_eq!(events[0]["args"]["duration_ms"], 10.0); } // ======================================================================== @@ -332,12 +325,10 @@ mod tests { assert_eq!(events[0]["cat"], "milestone"); assert!(events[0]["dur"].is_null()); // No duration for instant events assert_eq!(events[0]["args"]["success"], true); - assert!(events[0]["args"]["duration_ms"].is_null()); } #[test] fn test_span_event() { - // 8000 µs (= 8 ms exactly) avoids float-precision noise in duration_ms. let entries = vec![make_span_entry("config_load", 8000, Some(1000000), Some(1))]; let json = to_chrome_trace(&entries); @@ -352,7 +343,6 @@ mod tests { assert_eq!(events[0]["cat"], "wt"); assert!(events[0]["s"].is_null()); assert_eq!(events[0]["args"]["success"], true); - assert_eq!(events[0]["args"]["duration_ms"], 8.0); } #[test] diff --git a/src/trace/mod.rs b/src/trace/mod.rs index 5dac0787a..8c0ea6529 100644 --- a/src/trace/mod.rs +++ b/src/trace/mod.rs @@ -1,41 +1,20 @@ -//! Trace log parsing and Chrome Trace Format export. -//! -//! This module provides tools for analyzing `wt-trace` log output to understand -//! where time is spent during command execution. -//! -//! # Features -//! -//! - **Trace parsing**: Parse `wt-trace` log lines into structured entries -//! - **Chrome Trace Format**: Export for chrome://tracing or Perfetto visualization -//! - **SQL analysis**: Use Perfetto's trace_processor for queries -//! -//! # Usage -//! -//! ```bash -//! # Text timeline of one wt invocation -//! cargo run -p wt-perf -- timeline -- list --progressive -//! -//! # Chrome Trace Format JSON for Perfetto/chrome://tracing -//! # (--progressive forces TTY-gated events like `Skeleton rendered` to -//! # fire even though wt-perf pipes wt's stdout to /dev/null) -//! cargo run -p wt-perf -- timeline --chrome -- list --progressive > trace.json -//! -//! # From a trace.jsonl already captured to disk -//! cargo run -p wt-perf -- trace .git/wt/logs/trace.jsonl > trace.json -//! -//! # Analyze with SQL (requires: curl -LO https://get.perfetto.dev/trace_processor) -//! trace_processor trace.json -Q 'SELECT name, COUNT(*), SUM(dur)/1e6 as ms FROM slice GROUP BY name' -//! -//! # Find milestone events (instant events have dur=0) -//! trace_processor trace.json -Q 'SELECT name, ts/1e6 as ms FROM slice WHERE dur = 0' -//! -//! # Time from start to skeleton render -//! trace_processor trace.json -Q " -//! SELECT (skeleton.ts - start.ts)/1e6 as skeleton_ms -//! FROM slice start, slice skeleton -//! WHERE start.name = 'List collect started' -//! AND skeleton.name = 'Skeleton rendered'" -//! ``` +//! Trace log parsing and analysis. +//! +//! Tools for analyzing the `trace.jsonl` a `-vv` run captures (to +//! `.git/wt/logs/`), to understand where time went during a `wt` invocation: +//! +//! - [`emit`] — the authoritative `[wt-trace]` record emitter +//! - [`parse`] — `trace.jsonl` lines → structured [`TraceEntry`] values +//! - [`profile`] — the aggregate report behind `wt config state logs profile`: +//! where time goes (by command type / by context / slowest), parallelism, +//! and same-context cache misses +//! - [`timeline`] — the per-record view behind `wt-perf timeline` +//! - [`chrome`] — Chrome Trace Format export for visual critical-path +//! inspection in or chrome://tracing +//! +//! Capture with `wt -vv `, or let the `wt-perf timeline` helper run the +//! capture and render in one step (`cargo run -p wt-perf -- timeline -- list +//! --progressive`). pub mod chrome; pub mod emit; diff --git a/src/trace/profile.rs b/src/trace/profile.rs index adfa74c3c..15ee5aa67 100644 --- a/src/trace/profile.rs +++ b/src/trace/profile.rs @@ -198,27 +198,15 @@ pub struct Phase { /// Redundant-command analysis: the same `(command, context)` run more than once /// in a single invocation is a cache that should have hit but didn't. /// -/// The duplicate fields (`unique_commands`, `duplicated_commands`, -/// `extra_calls`, `same_context_*`) only consider commands whose work is fully -/// determined by `(command, context)`. A command that reads stdin -/// (`stdin=true`: a `claude -p` prompt, a diff piped to `git patch-id`) carries -/// input the command string doesn't capture, so two runs with identical -/// `(command, context)` may be entirely different work — it's counted in -/// `total_commands`/`total_time`/`contexts` but never reported as a duplicate. +/// Only commands whose work is fully determined by `(command, context)` are +/// considered. A command that reads stdin (`stdin=true`: a `claude -p` prompt, +/// a diff piped to `git patch-id`) carries input the command string doesn't +/// capture, so two runs with identical `(command, context)` may be entirely +/// different work — it never forms or joins a duplicate bucket. Cross-context +/// repeats aren't reported either: N worktrees each running `git status` is +/// expected fan-out, not a cache miss. #[derive(Debug, Clone, PartialEq, Serialize)] pub struct CacheReport { - /// Every command record, including stdin-reading ones. - pub total_commands: usize, - /// Distinct dedupable command strings (stdin-reading commands excluded). - pub unique_commands: usize, - pub contexts: usize, - /// Σ of every command duration, including stdin-reading ones. - #[serde(rename = "total_time_us", serialize_with = "ser_dur_us")] - pub total_time: Duration, - /// Distinct commands run more than once (in any context). - pub duplicated_commands: usize, - /// Extra runs beyond the first, regardless of context. - pub extra_calls: usize, /// Commands re-run within the same context, worst waste first. pub same_context_duplicates: Vec, /// Extra same-context runs beyond the first. @@ -685,10 +673,6 @@ impl Profile { impl CacheReport { /// Build a redundant-command report from parsed trace entries. pub fn from_entries(entries: &[TraceEntry]) -> Self { - let mut total_commands = 0; - let mut total_time_us = 0u64; - let mut cmd_counts: HashMap<&str, usize> = HashMap::new(); - let mut contexts: HashSet<&str> = HashSet::new(); // (command, context) → durations of every run, in microseconds. let mut pair_durations: HashMap<(&str, &str), Vec> = HashMap::new(); @@ -700,26 +684,20 @@ impl CacheReport { .. } = &entry.kind { - let ctx = entry.context.as_deref().unwrap_or("(none)"); - let dur_us = duration.as_micros() as u64; - total_commands += 1; - total_time_us += dur_us; - contexts.insert(ctx); // Duplicate analysis assumes (command, context) fully determines // a command's work. A command that reads stdin carries input the // command string doesn't capture, so two runs with identical // (command, context) may be entirely different work (a different // prompt piped to `claude -p`, a different diff to `git - // patch-id`). Count it in the totals above, but never let it - // form — or join — a duplicate bucket. + // patch-id`) — never let it form, or join, a duplicate bucket. if *reads_stdin { continue; } - *cmd_counts.entry(command.as_str()).or_default() += 1; + let ctx = entry.context.as_deref().unwrap_or("(none)"); pair_durations .entry((command.as_str(), ctx)) .or_default() - .push(dur_us); + .push(duration.as_micros() as u64); } } @@ -777,16 +755,7 @@ impl CacheReport { .then_with(|| a.command.cmp(&b.command)) }); - let duplicated_commands = cmd_counts.values().filter(|c| **c > 1).count(); - let extra_calls = cmd_counts.values().filter(|c| **c > 1).map(|c| c - 1).sum(); - CacheReport { - total_commands, - unique_commands: cmd_counts.len(), - contexts: contexts.len(), - total_time: Duration::from_micros(total_time_us), - duplicated_commands, - extra_calls, same_context_duplicates, same_context_extra_calls, same_context_extra: Duration::from_micros(same_context_extra_us), @@ -833,19 +802,21 @@ pub(super) enum Align { /// Pad rows into aligned columns, two spaces between columns, two-space indent. /// -/// Widths use `char` count — trace command shapes and durations are ASCII; -/// only a `[context]` (a branch name) can carry wide characters, and it sits in -/// the final left-aligned column. Trailing whitespace is trimmed per line. +/// Widths use display width (`unicode_width`), so a context cell carrying wide +/// characters (a CJK/emoji worktree name) aligns in any column. Trailing +/// whitespace is trimmed per line. /// /// Durations all render in one unit ([`fmt_dur`]) with two decimals, so /// right-aligning a duration column lines up both the decimal points and the /// `ms` suffix — no decimal-specific alignment is needed. pub(super) fn render_table(rows: &[Vec], aligns: &[Align]) -> String { + use unicode_width::UnicodeWidthStr; + let cols = aligns.len(); let mut widths = vec![0usize; cols]; for row in rows { for (i, cell) in row.iter().enumerate() { - widths[i] = widths[i].max(cell.chars().count()); + widths[i] = widths[i].max(cell.as_str().width()); } } @@ -854,7 +825,7 @@ pub(super) fn render_table(rows: &[Vec], aligns: &[Align]) -> String { let mut line = String::from(" "); for (i, cell) in row.iter().enumerate() { let last = i + 1 == row.len(); - let pad = widths[i].saturating_sub(cell.chars().count()); + let pad = widths[i].saturating_sub(cell.as_str().width()); match aligns[i] { Align::Left => { line.push_str(cell); @@ -986,6 +957,22 @@ mod tests { assert_eq!(command_type(""), ""); } + /// A wide-character context (CJK worktree name) in a non-final column must + /// not shift the columns after it — widths are display width, not chars. + #[test] + fn render_table_pads_by_display_width() { + let rows = vec![ + vec!["context".into(), "count".into()], + vec!["日本語".into(), "3".into()], + vec!["main".into(), "12".into()], + ]; + insta::assert_snapshot!(render_table(&rows, &[Align::Left, Align::Right]), @r" + context count + 日本語 3 + main 12 + "); + } + #[test] fn fmt_dur_is_milliseconds() { // One unit everywhere, two decimals — sub-millisecond and multi-second alike. @@ -1063,20 +1050,12 @@ mod tests { ]; let cache = CacheReport::from_entries(&entries); - // The stdin-reading commands are not duplicates … + // The stdin-reading commands are not duplicates; only the repeated + // `git status` is. assert_eq!(cache.same_context_duplicates.len(), 1); assert_eq!(cache.same_context_duplicates[0].command, "git status"); assert_eq!(cache.same_context_extra_calls, 1); assert_eq!(cache.same_context_extra, Duration::from_millis(1)); - // … nor counted in the cross-context duplicate tallies. - assert_eq!(cache.duplicated_commands, 1); - assert_eq!(cache.extra_calls, 1); - assert_eq!(cache.unique_commands, 1); // only `git status` is dedupable - - // … but they still count toward the totals (real commands, real time). - assert_eq!(cache.total_commands, 5); - assert_eq!(cache.total_time, Duration::from_millis(15)); - assert_eq!(cache.contexts, 1); } #[test] @@ -1172,12 +1151,6 @@ mod tests { } ], "cache": { - "total_commands": 2, - "unique_commands": 1, - "contexts": 1, - "total_time_us": 9000, - "duplicated_commands": 1, - "extra_calls": 1, "same_context_duplicates": [ { "command": "git status", diff --git a/src/trace/timeline.rs b/src/trace/timeline.rs index ec782add2..f030652bf 100644 --- a/src/trace/timeline.rs +++ b/src/trace/timeline.rs @@ -169,14 +169,28 @@ mod tests { } } + fn instant(name: &str, ts_us: u64) -> TraceEntry { + TraceEntry { + context: None, + kind: TraceEntryKind::Instant { + name: name.to_string(), + }, + start_time_us: Some(ts_us), + thread_id: Some(1), + } + } + #[test] fn renders_sorted_timeline_with_summary() { // Emit order swaps span and child cmd (parent finishes after child), - // so this exercises the sort-by-start-time guarantee. + // so this exercises the sort-by-start-time guarantee. The instant + // event renders as an `event` row with an empty duration cell, stays + // out of the subprocess summary, and doesn't extend the traced span. let entries = vec![ cmd("git rev-parse HEAD", Some("repo"), 50, 4_000, 1, true), span("prewarm", 30, 4_100, 1), span("init_logging", 0, 8, 1), + instant("Skeleton rendered", 3_000), span("user_config_load", 4_200, 280, 38), ]; // Wall = 6ms; traced = 4.48ms (4.2ms start → 4.48ms end); @@ -184,11 +198,12 @@ mod tests { insta::assert_snapshot!( render_timeline(&entries, Duration::from_micros(6_000)), @" - ts(ms) dur tid kind name - 0.000 0.01ms 1 span init_logging - 0.030 4.10ms 1 span prewarm - 0.050 4.00ms 1 cmd git rev-parse HEAD [repo] - 4.200 0.28ms 38 span user_config_load + ts(ms) dur tid kind name + 0.000 0.01ms 1 span init_logging + 0.030 4.10ms 1 span prewarm + 0.050 4.00ms 1 cmd git rev-parse HEAD [repo] + 3.000 1 event Skeleton rendered + 4.200 0.28ms 38 span user_config_load 1 subprocess totaling 4.00ms (slowest: 4.00ms git rev-parse HEAD [repo]) traced: 4.48ms (first → last record) diff --git a/tests/integration_tests/config_state.rs b/tests/integration_tests/config_state.rs index b3a822512..f88d510cd 100644 --- a/tests/integration_tests/config_state.rs +++ b/tests/integration_tests/config_state.rs @@ -456,12 +456,6 @@ fn test_logs_profile_json(repo: TestRepo) { } ], "cache": { - "total_commands": 5, - "unique_commands": 3, - "contexts": 2, - "total_time_us": 32000, - "duplicated_commands": 2, - "extra_calls": 2, "same_context_duplicates": [ { "command": "git config --list", From 6b3bdc67f45edc6c8147a24c7440aa25fba1938b Mon Sep 17 00:00:00 2001 From: Maximilian Roos Date: Thu, 9 Jul 2026 21:09:40 -0700 Subject: [PATCH 4/6] docs(tend): fix cross-reference left by the merge from main MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Main's diagnostic-section addition calls the per-render cache analysis 'a separate tool', pointing at the wt-perf cache-check recipe — which this branch already cut over to wt config state logs profile. Reword: it's the same report against a statusline capture. Co-Authored-By: Claude Fable 5 --- .claude/skills/running-tend/SKILL.md | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/.claude/skills/running-tend/SKILL.md b/.claude/skills/running-tend/SKILL.md index e5b775934..4c39f14e9 100644 --- a/.claude/skills/running-tend/SKILL.md +++ b/.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: From b9ab5802877bb8515b1b99b892c869a9971a9770 Mon Sep 17 00:00:00 2001 From: Maximilian Roos Date: Thu, 9 Jul 2026 21:10:06 -0700 Subject: [PATCH 5/6] docs(design): drop the proposal from the merge candidate Per the design/ convention, proposals guide implementation PRs but don't land on main. The doc remains in this branch's history (b22aced85) and its content is implemented by the commits above. Co-Authored-By: Claude Fable 5 --- design/simplify-bench-perf.md | 220 ---------------------------------- 1 file changed, 220 deletions(-) delete mode 100644 design/simplify-bench-perf.md diff --git a/design/simplify-bench-perf.md b/design/simplify-bench-perf.md deleted file mode 100644 index 0a4d7ce65..000000000 --- a/design/simplify-bench-perf.md +++ /dev/null @@ -1,220 +0,0 @@ -# Design: canonicalize the benchmark / wt-perf system - -Status: proposal (no production code). This answers one question: - -> The perf tooling has grown five layers: trace emission, the analysis library -> in `src/trace/`, the `wt-perf` helper crate, seven Criterion bench targets -> with a daily CI run, and `benches/CLAUDE.md`. Where do they duplicate each -> other, and what can be canonicalized or cut without losing meaningful -> capability? - -Short answer: the emission side (`src/trace/emit.rs` and the `CommandTrace` -chokepoint) is already canonical and stays untouched. The duplication is on the -*consumption* side: two CLIs expose the same analysis, the timeline renderer -re-implements label formatting the library already owns, the one analysis the -library doesn't compute keeps an 80-line SQL section alive in -`benches/CLAUDE.md`, the warm/cold iteration pattern is copy-pasted across five -bench files, and three bench groups guard the same regression shape. Each -proposal below deletes one of those parallel paths. - -## Summary of recommendations - -1. **Delete `wt-perf cache-check`.** Its output is the `cache` field of - `wt config state logs profile --format=json`: the same `CacheReport`, - built from the same entries. -2. **Move the timeline renderer into `worktrunk::trace`** and render it with - the library's existing label/table/duration helpers. `wt-perf` keeps the - harness work (spawn `wt -vv`, external wall clock, cold invalidation) and - delegates all rendering. -3. **Add a `by_context` table to `Profile`, then cut the trace_processor SQL - section from `benches/CLAUDE.md`.** Per-worktree subprocess totals are the - only documented query `logs profile` doesn't already answer. -4. **One shared warm/cold bench runner in `wt_perf`.** Hoist `run_benchmark` - from `benches/list.rs` into the library; the `PerIteration` rationale is - written once, on the helper, instead of five times across bench files. -5. **Prune the bench matrix**: `real_repo` keeps only the 8-worktree variants, - `cow_copy` is deleted, and the `remove_e2e/first_output` arm (a duplicate of - `first_output/remove`) is deleted. Saves roughly 15–20 minutes of the ~80 - minute daily run. -6. **Move the `wt-perf` CLI tests into the `wt-perf` package.** In-package - integration tests get `CARGO_BIN_EXE_wt-perf` natively, which retires the - dummy `builds.rs` and drops `wt-perf` from the nextest setup script. -7. **Fold `mixed-W-B` into `parse_config`** so `wt-perf setup` has one config - parser instead of a parser plus a special case. - -Items 1–4 and 6–7 are pure consolidation (no signal lost). Item 5 trades named -benchmark series for CI time; the losses are itemized below and each has a -covering twin or a documented fallback. - -## The system today - -| Layer | Where | Size | Role | -|-------|-------|------|------| -| Emission | `src/trace/emit.rs` + `src/logging.rs` layers | 435 | `CommandTrace`/`Span`/`instant` → `trace.jsonl` / `trace.log` | -| Analysis library | `src/trace/{parse,profile,chrome}.rs` | ~2,060 | parse back; `Profile`/`CacheReport`; Chrome Trace export | -| wt-perf crate | `tests/helpers/wt-perf/` | ~1,530 | fixture builders (lib) + CLI: `setup`, `invalidate`, `trace`, `cache-check`, `timeline` | -| Benches | `benches/*.rs` (7 targets) | 1,255 | Criterion; daily `benchmarks.yaml` run (~80 min) feeding the gist time series | -| Docs | `benches/CLAUDE.md` | 352 | run examples, cache handling, fixture notes, trace_processor SQL | - -Analysis consumers: `wt config state logs profile` (text + JSON), `wt diagnose` -(embeds the rendered profile), and the `wt-perf` CLI. - -The canonicalization principle the proposals converge on: **capture and -harness work lives in `wt-perf`; analysis lives in `worktrunk::trace` with -`wt config state logs profile` as its one CLI surface.** `wt-perf timeline` -earns its place because it does harness work a passive reader can't (spawn -under `-vv`, measure spawn→wait wall externally, invalidate for cold runs); -`cache-check` doesn't, because it's a passive reader of the same file -`logs profile` reads. - -## Proposals - -### 1. Delete `wt-perf cache-check` - -`cache_check()` in `tests/helpers/wt-perf/src/main.rs` is -`CacheReport::from_entries` + `serde_json::to_string_pretty`. `handle_logs_profile` -with `--format=json` serializes `Profile`, whose `cache` field is the same -struct from the same entries. Two documented entry points for one analysis; -`jq .cache` closes the gap. Delete the subcommand and its `after_long_help`. - -### 2. One renderer per view: move the timeline into `worktrunk::trace` - -`render_timeline`/`describe` in `wt-perf/src/main.rs` (~120 lines plus -snapshots) duplicate the library: - -- `describe()` re-implements `profile.rs::command_label` (the `cmd [ctx]` + - `(ok=false)` / `(err: …)` shape), and the two have already drifted: the - timeline pads two spaces before the failure marker, the profile one. -- The timeline aligns columns with `tabwriter` while `profile.rs` has its own - `render_table`; durations render via `Duration`'s `Debug` (`4.5ms`, `1.5s`) - in one and fixed-point `fmt_dur` (`4.50ms`) in the other. - -Move the renderer into `src/trace/` as -`render_timeline(&[TraceEntry], wall: Duration) -> String`, built on -`command_label`, `render_table`, and `fmt_dur`. `wt-perf timeline` keeps the -spawn/invalidate/measure logic and calls it. The `tabwriter` dependency and the -duplicated label code go away; timeline durations switch to the fixed-point -format (a cosmetic change to a dev tool's output). - -Also under this item: the `logs profile` help currently points users at -`cargo run -p wt-perf -- timeline`, a tool that exists only in this repo. Move -that pointer to `benches/CLAUDE.md`, where every reader can actually run it. - -### 3. `by_context` in `Profile`; retire the SQL section - -`benches/CLAUDE.md` carries ~80 lines of trace_processor SQL for three -questions. `Profile` already answers nearly all of it: - -| CLAUDE.md query | Profile field | -|-----------------|---------------| -| #1 slowest individual commands | `slowest` | -| #1 total time by command type (hand-rolled `CASE` buckets) | `by_type` (via `command_type`, which the SQL approximates) | -| #2 parallelism factor | `parallelism`, `peak_concurrency` | -| #3 phase durations from milestones | `phases`, `key_intervals` | -| #3 per-worktree totals (`EXTRACT_ARG(args.context)`) | **missing** | - -Add `by_context: Vec` (context, count, total; busiest first) to -`Profile` — a few lines in `from_entries`, one more table in `render_text`, -one more array in the JSON. Then the SQL section reduces to one line: open the -Chrome JSON in Perfetto for visual critical-path inspection, which is the one -thing SQL-over-slices was never good at anyway (the section itself says so). -The `command_type` bucketing also stops having a hand-maintained SQL shadow -that must track new command shapes. - -`chrome.rs` stays: Perfetto visualization is the remaining consumer and has no -substitute. - -### 4. One warm/cold bench runner - -`benches/list.rs` has `run_benchmark` (binary, repo, cold flag, args, env); -`remove.rs`, `picker_preview.rs`, `alias.rs`, and `time_to_first_output.rs` -re-inline the same warm/cold split, and each copy carries its own multi-line -retelling of why `BatchSize::PerIteration` beats `SmallInput`. Hoist the -helper into the `wt_perf` library (it already owns `invalidate_caches_auto`, -the other half of the pattern), document the `PerIteration` rationale once on -it, and add the success assertion most call sites bolt on. Bench files keep -only what's genuinely per-bench: fixtures, args, and setup closures like -`recreate_worktree`. - -`benches/CLAUDE.md`'s "Cache Handling" section then references the helper -instead of prescribing the pattern for hand-rolling. - -### 5. Prune the bench matrix - -The daily run costs ~80 minutes. Three cuts where cost × redundancy is -highest: - -- **`real_repo`: keep `{warm,cold}/8`, drop the 1- and 4-worktree variants.** - Each variant clones rust-lang/rust locally and the cold ones rebuild - 59k-entry indexes per iteration; this group dominates the run. The - worktree-count scaling *shape* is already tracked at criterion cadence by - `worktree_scaling` (1/4/8, synthetic); what's unique to `real_repo` is - real-repo magnitude and the cold penalty, which the 8-worktree endpoints - keep. Lost: the real-repo scaling curve's interior points. -- **Delete `cow_copy`.** It compares production `copy_dir_recursive` against a - 40-line serial copy that exists only inside the bench — a shadow - implementation maintained to validate a settled design choice (rayon - parallel copy). Six size/shape variants × 2 impls at daily cadence guard a - code path that changes only when `reflink_copy` or the copy loop does. - Lost: a throughput series for `wt step copy-ignored`. If that loss bites, - the fallback is re-adding a single parallel-only variant. -- **Delete the `remove_e2e/first_output` arm.** Its own comment says it is - "the same as time_to_first_output"; two series measure one quantity from two - files. The cross-group comparison (`remove_e2e/no_hooks` vs - `first_output/remove`) still works — both land in the same gist. - -Considered and skipped: thinning `skeleton`/`worktree_scaling` to 1-and-8. -They're cheap (modest fixture, 15s budgets), and the interior point is what -distinguishes linear from superlinear drift. - -### 6. Move the wt-perf CLI tests into the wt-perf package - -`tests/integration_tests/analyze_trace.rs` (four tests of `wt-perf trace`) -lives in the main integration suite, so it reaches the binary through -`workspace_bin()` — which is why the nextest setup script pre-builds `wt-perf` -and why the crate carries a dummy `tests/builds.rs` whose only job is forcing -binary compilation. Integration tests *inside* the `wt-perf` package get -`CARGO_BIN_EXE_wt-perf` from cargo directly, and building them builds the -binary. Move the four tests there; delete `builds.rs` (the real tests now do -its job); drop `wt-perf` from `.config/nextest.toml`'s setup script (mock-stub -still needs the layer, so the script itself stays). - -Behavior change: `cargo test --test integration` no longer runs these four -tests; full-workspace runs (the gate, CI, `cargo nextest run`) still do, since -`wt-perf` is in `default-members`. - -### 7. One config parser in `wt-perf setup` - -`parse_config` handles `typical-N`/`branches-N[-M]`/`divergent`/`picker-test`; -`mixed-W-B` is parsed by a separate `parse_mixed` in `main.rs` with its own -`match` arm and an `unreachable!`. Return an enum -(`Flat(RepoConfig)` / `Mixed { worktrees, branches }`) from `parse_config` and -the special case collapses. The fixture builders themselves -(`create_repo_at` vs `create_mixed_repo_at`) share only trivial plumbing (init, -auto-maintenance config, gc) — worth a small shared `init_repo` helper, but no -deeper unification: their fixture shapes are deliberately different, and -reshaping fixtures moves every benchmark's level in the gist time series. - -## What stays as is - -- **Emission** (`emit.rs`, the `CommandTrace` chokepoint, the two-rendering - split in `logging.rs`): already single-path by design. -- **The wt-perf binary as a separate package.** Folding its commands into `wt` - would ship fixture generators to users, and cargo-dist ships every `[[bin]]` - in the main crate (the documented reason the helper packages exist). -- **Seven separate `[[bench]]` targets.** Merging them saves link time but - costs per-target compile selectivity (`cargo bench --bench list` builds one - target), which matters more during iteration. -- **`wt-perf trace`** (jsonl → Chrome JSON for an already-captured file, e.g. a - CI artifact): the file-input twin of `timeline --chrome`, five lines of CLI - over the library. -- **Fixture shapes and surviving benchmark IDs**: the gist time series keys on - them. - -## Sequencing - -Items 1–4, 6, 7 are one consolidation PR each (or one combined); no series is -affected. Item 5 ends three series and should land as its own PR so the -discontinuity in the gist has a single date and commit to point at. -`benches/CLAUDE.md` shrinks in the same PRs that obsolete its sections (the -SQL section with item 3, the hand-rolled cache-handling pattern with item 4). From bb84fd5bd77887a35a9199bdc8227457ec92527e Mon Sep 17 00:00:00 2001 From: Maximilian Roos Date: Fri, 10 Jul 2026 02:54:42 -0700 Subject: [PATCH 6/6] docs: fold in draft-review fixes on the perf consolidation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The profile module spec referenced a nonexistent `wt diagnose` command (the consumer is the -vv diagnostic report), and the expected-numbers table still documented the deleted remove_e2e/first_output variant — repointed at the surviving first_output/remove. Co-Authored-By: Claude Fable 5 --- benches/CLAUDE.md | 2 +- src/trace/profile.rs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/benches/CLAUDE.md b/benches/CLAUDE.md index 2b88a1ef5..fe9f4b14d 100644 --- a/benches/CLAUDE.md +++ b/benches/CLAUDE.md @@ -184,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 diff --git a/src/trace/profile.rs b/src/trace/profile.rs index 15ee5aa67..209bd316b 100644 --- a/src/trace/profile.rs +++ b/src/trace/profile.rs @@ -22,7 +22,7 @@ //! data over `&[TraceEntry]` and carries no styling, so it compiles without the //! `cli` feature and is shared by `wt config state logs profile` (which renders //! via [`Profile::render_text`] or serializes the struct for `--format=json`) and -//! `wt diagnose` (which embeds the rendered text). The struct's `Serialize` impl +//! the `-vv` diagnostic report (`diagnostic.md`, which embeds the rendered text). The struct's `Serialize` impl //! is the single canonical JSON source. //! //! [`benches/CLAUDE.md`]: ../../../benches/CLAUDE.md