diff --git a/.claude/skills/running-tend/SKILL.md b/.claude/skills/running-tend/SKILL.md index 8984389b3d..4c39f14e9d 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: @@ -288,9 +288,9 @@ Discovery shortcut: a recent green CI run on `main` flags cargo-install drift di ## Weekly Maintenance: Statusline Cache-Check Detect new in-process cache-miss duplicates introduced by recent changes by -running `wt-perf cache-check` against a real `wt list statusline --claude-code` -trace. The render runs on every Claude Code prompt redraw, so duplicate git -subprocesses there compound into measurable fseventsd / IPC load. +profiling a real `wt list statusline --claude-code` trace. The render runs on +every Claude Code prompt redraw, so duplicate git subprocesses there compound +into measurable fseventsd / IPC load. ```bash # Run from any worktree of this repo @@ -300,12 +300,12 @@ cat > /tmp/statusline-input.json <<'EOF' EOF sed -i '' "s|REPLACE_WITH_CWD|$PWD|" /tmp/statusline-input.json -RUST_LOG=debug cargo run --release -- list statusline --claude-code \ - < /tmp/statusline-input.json 2>&1 \ - | cargo run -p wt-perf -- cache-check +cargo run --release -- -vv list statusline --claude-code \ + < /tmp/statusline-input.json > /dev/null +cargo run --release -- config state logs profile --format=json | jq .cache ``` -The report flags commands invoked more than once with the same context. +The `.cache` report flags commands invoked more than once with the same context. Triage each duplicate: - **Legitimate** (different cwd, different ref form that can't be normalized, diff --git a/.config/nextest.toml b/.config/nextest.toml index 580e397896..b45c5c1a7f 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 d9891d846b..62bb7586a6 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. ### Fixed diff --git a/Cargo.lock b/Cargo.lock index 4ad9004ff7..580745de3e 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 87f99bd1a4..46ade6100d 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 @@ -335,10 +337,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 3b1bc7d763..fe9f4b14d7 100644 --- a/benches/CLAUDE.md +++ b/benches/CLAUDE.md @@ -51,7 +51,7 @@ cargo bench --bench list -- --exact full/cold # One exact ID To skip the slow real-repo and divergent groups, target the synthetic groups directly: `cargo bench --bench list skeleton`, `cargo bench --bench list worktree_scaling`, or `cargo bench --bench list full`. Run them sequentially if you want more than one. -The `full` group is the place to start when `wt list` regresses on a real mix of worktrees and branches: the cold/warm split says whether the cost is the persistent-cache fill (cold) or the per-process re-fork (warm). A `full` wall time can't be split by side (the git subprocesses overlap on the rayon pool), so to localize a regression, trace one invocation and bucket subprocess time per worktree (query #3 below); `worktree_scaling` and `divergent_branches` track the worktree side and branch side respectively at criterion cadence. +The `full` group is the place to start when `wt list` regresses on a real mix of worktrees and branches: the cold/warm split says whether the cost is the persistent-cache fill (cold) or the per-process re-fork (warm). A `full` wall time can't be split by side (the git subprocesses overlap on the rayon pool), so to localize a regression, trace one invocation and read the profile's BY CONTEXT table ("Analyzing a trace" below); `worktree_scaling` and `divergent_branches` track the worktree side and branch side respectively at criterion cadence. ## WORKTRUNK_FIRST_OUTPUT @@ -89,21 +89,11 @@ so bench iterations read from prior iterations unless invalidated. **Rule:** if a benchmark runs a `wt` subcommand that populates these caches, every iteration must start cold — otherwise iter 1 measures the real cost and iter 2+ measure -a cache hit. Invalidate via `criterion::Bencher::iter_batched` with -`wt_perf::invalidate_caches_auto` as the setup closure (see the cold-cache variants in -`benches/list.rs` and `benches/remove.rs` for the pattern). - -**Pass `BatchSize::PerIteration`, not `BatchSize::SmallInput`.** When the setup -invalidates a cache that the routine repopulates, the batch size matters: -`SmallInput` calls `setup()` once per batch up front, then times the routines -back-to-back inside one timing window, so only iter 1 per batch is actually cold -— iters 2-N hit a cache that the previous iter just populated. The reported -"cold" median is a warm-biased average. `PerIteration` runs `setup → time(routine)` -per iter, so every measured iter is genuinely cold. The setup is far cheaper than -a `wt` subprocess, so per-iter `Instant::now` overhead doesn't dominate. When the -fix landed across `list.rs` / `remove.rs` / `time_to_first_output.rs`, cold variance -tightened (e.g. `first_output/remove` spread 2.4ms → 0.65ms) and the median rose -to its true cold cost (e.g. `remove_e2e/first_output` 48ms → 86ms). +a cache hit. Run the iteration through `wt_perf::bench_wt`, the one home of the +warm/cold strategy (plain `iter` warm; invalidate-per-iteration cold — its doc +comment carries the `BatchSize::PerIteration` rationale). A cold benchmark whose +setup is not plain invalidation (e.g. `remove_e2e` recreating the removed +worktree) uses `iter_batched` with `BatchSize::PerIteration` directly. `invalidate_caches_auto` clears: @@ -194,7 +184,7 @@ because its ~15 GiB fixture must never build on a hosted CI runner): | `prune_e2e/dry_run_warm` | ~90 ms | steady-state re-scan, probes hit sha_cache | | `prune_e2e/live` | ~620 ms | cold scan + serial removal of the 8 candidates (~60 ms each, under the scan write lock) | | `prune_real_repo/dry_run_warm` | ~0.3–0.8 s | steady-state scan of 72 items (36 worktrees + 36 branches) at 331k-commit scale | -| `remove_e2e/first_output` | ~86 ms | single-target validation up to first output | +| `first_output/remove` | ~86 ms | single-target validation up to first output (`benches/time_to_first_output.rs`) | Cold and live at rust scale are **one-shot timelines, not criterion groups** (a cold criterion iteration costs ~1 min in re-hashing statuses alone; a live @@ -309,7 +299,7 @@ cargo run -p wt-perf -- setup typical-8 --persist # picker-test - Config for wt switch interactive picker testing # Invalidate caches for cold run -cargo run -p wt-perf -- invalidate /tmp/wt-perf-typical-8/main +cargo run -p wt-perf -- invalidate /tmp/wt-perf-typical-8 ``` ### Generating traces @@ -351,103 +341,35 @@ prelude/epilogue not visible to the trace — process spawn, dyld, code that runs before `init_logging` registers the trace epoch, and the exit path after the last span drops. -### Querying with trace_processor +### Analyzing a trace -Install [trace_processor](https://perfetto.dev/docs/analysis/trace-processor) for SQL analysis: +`wt config state logs profile [FILE]` answers the three questions below from a +captured `trace.jsonl` without leaving the terminal: subprocess time by command +type and by worktree (BY COMMAND TYPE / BY CONTEXT), the slowest individual +jobs, the parallelism factor and peak concurrency, same-context duplicate +commands (CACHE), and the collect milestones (KEY INTERVALS / PHASES). +`--format=json` emits the same data for scripting. ```bash -curl -LO https://get.perfetto.dev/trace_processor && chmod +x trace_processor +wt -vv list --progressive +wt config state logs profile # human report +wt config state logs profile --format=json | jq .cache ``` +For visual critical-path inspection — the one thing the aggregate report can't +show — open the Chrome Trace JSON (`wt-perf timeline --chrome`, or `wt-perf +trace` on an existing `trace.jsonl`) in 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 e17c44ea44..993e4e9719 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 53c63f3b7d..0000000000 --- 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 d0044020ef..2b446fbae3 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 f6924b09f3..f0620334ff 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 0a19d910b5..3af8fb8971 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 16fec8f237..e0e1036cc7 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 fa471bb2e1..e049610b5d 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 e165b8a0cd..35f84e8691 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/chrome.rs b/src/trace/chrome.rs index 1494d48ed1..c50acbf40c 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 d3543694c5..8c0ea6529f 100644 --- a/src/trace/mod.rs +++ b/src/trace/mod.rs @@ -1,49 +1,30 @@ -//! 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; 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 9abed86129..209bd316b0 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 +//! 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 @@ -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 { @@ -184,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. @@ -285,8 +287,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 +329,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 +350,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 +389,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 +458,7 @@ impl Profile { thread_count: threads.len(), key_intervals, by_type, + by_context, slowest, cache: CacheReport::from_entries(entries), phases, @@ -525,6 +549,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)); @@ -625,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(); @@ -640,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); } } @@ -717,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), @@ -766,26 +795,28 @@ fn concurrency(intervals: &[(u64, u64)]) -> (Option, Option) { } #[derive(Clone, Copy)] -enum Align { +pub(super) enum Align { Left, Right, } /// 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. -fn render_table(rows: &[Vec], aligns: &[Align]) -> String { +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()); } } @@ -794,7 +825,7 @@ 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); @@ -820,7 +851,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) } @@ -926,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. @@ -1003,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] @@ -1094,6 +1133,13 @@ mod tests { "avg_us": 4500 } ], + "by_context": [ + { + "context": "main", + "count": 2, + "total_us": 9000 + } + ], "slowest": [ { "dur_us": 5000, @@ -1105,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/snapshots/worktrunk__trace__profile__tests__renders_full_report.snap b/src/trace/snapshots/worktrunk__trace__profile__tests__renders_full_report.snap index dff3289765..78ee9ac9b5 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 b53da56f91..6fe5bf1be9 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 0000000000..f030652bf7 --- /dev/null +++ b/src/trace/timeline.rs @@ -0,0 +1,230 @@ +//! 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), + } + } + + 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. 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); + // 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] + 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) + 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 558aa3c591..c9552b1782 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 b522edf32c..496eb2d8b2 100644 --- a/tests/helpers/wt-perf/src/lib.rs +++ b/tests/helpers/wt-perf/src/lib.rs @@ -108,6 +108,50 @@ impl RepoConfig { } } +/// A parsed `wt-perf setup` config string. +/// +/// Most configs map onto the flat [`RepoConfig`] (every worktree/branch +/// identical); the composite fixtures build varied states instead: +/// `mixed-W-B` via [`create_mixed_repo_at`], `prune-M-U` via +/// [`create_prune_repo_at`]. (`prune-real[-M-U]` is not a `SetupConfig`: +/// it is cache-managed under `target/bench-repos/` and takes no path — see +/// [`ensure_prune_real_repo`].) +pub enum SetupConfig { + Flat(RepoConfig), + Mixed { worktrees: usize, branches: usize }, + Prune { merged: usize, unmerged: 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) + } + SetupConfig::Prune { merged, unmerged } => { + create_prune_repo_at(*merged, *unmerged, base_path); + (merged + unmerged + 1, merged + unmerged) + } + } + } +} + +/// Parse a `A-B` config string (e.g. `mixed-4-8`) into its two counts. +pub fn parse_pair(config: &str, prefix: &str) -> Option<(usize, usize)> { + let rest = config.strip_prefix(prefix)?; + let (a, b) = rest.split_once('-')?; + Some((a.parse().ok()?, b.parse().ok()?)) +} + /// 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 +163,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(); @@ -161,6 +252,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"]); +} + /// Run a git plumbing command against a scratch `GIT_INDEX_FILE`, panicking on /// failure and returning trimmed stdout. Used to build commits without /// touching the repo's working tree or real index (see @@ -192,23 +305,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); @@ -785,15 +882,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")); @@ -1213,39 +1302,45 @@ 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 +/// - `prune-M-U` - M squash-merged candidates + U unmerged (prune workload) /// - `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((worktrees, branches)) = parse_pair(s, "mixed-") { + return Some(SetupConfig::Mixed { + worktrees, + branches, + }); + } + + if let Some((merged, unmerged)) = parse_pair(s, "prune-") { + return Some(SetupConfig::Prune { merged, unmerged }); } 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 c0fdd52720..8459c4cd6b 100644 --- a/tests/helpers/wt-perf/src/main.rs +++ b/tests/helpers/wt-perf/src/main.rs @@ -8,11 +8,9 @@ use std::process::{Command, Stdio}; use std::time::{Duration, Instant}; use clap::{Parser, Subcommand}; -use worktrunk::trace::{TraceEntry, TraceEntryKind, TraceResult}; use wt_perf::{ - PRUNE_REAL_MERGED, PRUNE_REAL_UNMERGED, canonicalize, create_mixed_repo_at, - create_prune_repo_at, create_repo_at, ensure_prune_real_repo, invalidate_caches_auto, - parse_config, + PRUNE_REAL_MERGED, PRUNE_REAL_UNMERGED, canonicalize, ensure_prune_real_repo, + invalidate_caches_auto, parse_config, parse_pair, }; #[derive(Parser)] @@ -68,17 +66,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, @@ -126,19 +113,15 @@ fn main() { path, persist, } => { - // `mixed-W-B` / `prune-M-U` / `prune-real[-M-U]`: composite - // fixtures handled separately since they don't map onto the flat - // `RepoConfig`. Test `prune-real` before `prune-` so the pair - // parser never sees it. + // `prune-real[-M-U]`: cache-managed rust-scale fixture (built once + // under target/bench-repos/, repaired after a live prune consumes + // its candidates) — takes no --path and never offers cleanup. + // Tested before parse_config so its `prune-` arm never sees it. let prune_real = if config == "prune-real" { Some((PRUNE_REAL_MERGED, PRUNE_REAL_UNMERGED)) } else { parse_pair(&config, "prune-real-") }; - - // The rust-scale fixture is cache-managed (built once under - // target/bench-repos/, repaired after a live prune consumes its - // candidates), so it takes no --path and never offers cleanup. if let Some((merged, unmerged)) = prune_real { if path.is_some() { eprintln!( @@ -169,35 +152,26 @@ fn main() { return; } - let mixed = parse_pair(&config, "mixed-"); - let prune = parse_pair(&config, "prune-"); - - let repo_config = if mixed.is_some() || prune.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!( - " prune-M-U - M squash-merged candidates + U unmerged worktrees/branches (wt step prune workload)" - ); - eprintln!( - " prune-real[-M-U] - rust-lang/rust clone + M squash-merged candidates + U unmerged worktrees/branches, cached in target/bench-repos (default {PRUNE_REAL_MERGED}-{PRUNE_REAL_UNMERGED}; first run clones from network)" - ); - 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!( + " prune-M-U - M squash-merged candidates + U unmerged worktrees/branches (wt step prune workload)" + ); + eprintln!( + " prune-real[-M-U] - rust-lang/rust clone + M squash-merged candidates + U unmerged worktrees/branches, cached in target/bench-repos (default {PRUNE_REAL_MERGED}-{PRUNE_REAL_UNMERGED}; first run clones from network)" + ); + 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(); @@ -212,23 +186,7 @@ fn main() { }; eprintln!("Creating {} repo...", config); - let (worktrees, branches) = match (mixed, prune, &repo_config) { - (Some((w, b)), _, _) => { - create_mixed_repo_at(w, b, &base_path); - (w, b) - } - (None, Some((m, u)), _) => { - create_prune_repo_at(m, u, &base_path); - (m + u + 1, m + u) - } - (None, None, Some(cfg)) => { - create_repo_at(cfg, &base_path); - (cfg.worktrees, cfg.branches) - } - (None, None, None) => { - unreachable!("repo_config is Some when composites are None") - } - }; + let (worktrees, branches) = spec.create_at(&base_path); let mut parts = vec![format!("main @ {}", base_path.display())]; if worktrees > 1 { @@ -239,7 +197,7 @@ fn main() { } eprintln!("Created: {}", parts.join(", ")); eprintln!(); - let example_args = if prune.is_some() { + let example_args = if matches!(spec, wt_perf::SetupConfig::Prune { .. }) { "step prune --dry-run --min-age 0s" } else { "list --progressive" @@ -291,11 +249,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, @@ -305,13 +258,6 @@ fn main() { } } -/// Parse a `N-M` config string (e.g. `mixed-4-8`) into its two counts. -fn parse_pair(config: &str, prefix: &str) -> Option<(usize, usize)> { - let rest = config.strip_prefix(prefix)?; - let (a, b) = rest.split_once('-')?; - Some((a.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 @@ -414,7 +360,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() { @@ -464,119 +410,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 { @@ -618,20 +451,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 d2afa21996..0000000000 --- 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 632043ace1..a033d60afa 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 e49b17ab0f..f88d510cd7 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, @@ -444,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", diff --git a/tests/integration_tests/mod.rs b/tests/integration_tests/mod.rs index a79e27bed7..36b7341a7e 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 3c212e9a1e..532d854799 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 129e192ee2..886de2ff93 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