Exclude diagnostic collector commands from profiles

src/diagnostic.rs

@@ -330,6 +330,15 @@ pub(crate) fn write_if_verbose(verbose: u8, command_line: &str, error_msg: Optio
         return;
     }
 
+    // The collector runs after the command and writes to the same trace. Mark
+    // all of its subprocesses at the source so aggregate profiles can exclude
+    // them without recognizing individual commands or relying on their order.
+    worktrunk::trace::emit::with_diagnostic_context(|| {
+        write_diagnostic(command_line, error_msg);
+    });
+}
+
+fn write_diagnostic(command_line: &str, error_msg: Option<&str>) {
     // Use Repository::current() which honors the -C flag
     let Ok(repo) = Repository::current() else {
         return;

src/shell_exec.rs

@@ -826,6 +826,7 @@ pub const SUBPROCESS_BOUNDED_TARGET: &str = "worktrunk::subprocess_bounded";
 /// that [`log_output`] prepends to each block in `subprocess.log`, so the two
 /// render the command identically.
 fn command_header(cmd: &str, context: Option<&str>) -> String {
+    let context = crate::trace::emit::diagnostic_context().or(context);
     match context {
         Some(ctx) => format!("$ {cmd} [{ctx}]"),
         None => format!("$ {cmd}"),

src/trace/emit.rs

@@ -79,6 +79,7 @@
 //! so it stays segmentable and joins back to this record via `seq`.
 
 use std::borrow::Cow;
+use std::cell::Cell;
 use std::fmt::Display;
 use std::sync::OnceLock;
 use std::sync::atomic::{AtomicU64, Ordering};
@@ -123,6 +124,41 @@ pub fn thread_id() -> u64 {
 /// regardless of whether the file layers are active. Starts at 1.
 static CMD_SEQ: AtomicU64 = AtomicU64::new(1);
 
+/// Reserved context for subprocesses that build the `-vv` diagnostic report.
+///
+/// The raw trace retains these records, while aggregate profiles exclude them
+/// so they describe the command being diagnosed rather than its collector.
+pub const DIAGNOSTIC_CONTEXT: &str = "(diagnostic)";
+
+thread_local! {
+    static IN_DIAGNOSTIC_CONTEXT: Cell<bool> = const { Cell::new(false) };
+}
+
+struct DiagnosticContextGuard {
+    previous: bool,
+}
+
+impl Drop for DiagnosticContextGuard {
+    fn drop(&mut self) {
+        IN_DIAGNOSTIC_CONTEXT.set(self.previous);
+    }
+}
+
+/// Run `f` with subprocess trace records assigned to [`DIAGNOSTIC_CONTEXT`].
+///
+/// The override is thread-local so command work still completing on another
+/// thread keeps its original context. Nested scopes restore the prior state.
+pub fn with_diagnostic_context<T>(f: impl FnOnce() -> T) -> T {
+    let previous = IN_DIAGNOSTIC_CONTEXT.replace(true);
+    let _guard = DiagnosticContextGuard { previous };
+    f()
+}
+
+/// Active trace-context override for the current thread, if any.
+pub(crate) fn diagnostic_context() -> Option<&'static str> {
+    IN_DIAGNOSTIC_CONTEXT.get().then_some(DIAGNOSTIC_CONTEXT)
+}
+
 /// Emit a completed-command record (`ok=true`/`ok=false`).
 ///
 /// Private and taking `&CommandTrace`: every per-command field but the
@@ -244,7 +280,7 @@ impl CommandTrace {
     /// the captured start time brackets the subprocess.
     pub fn new(context: Option<&str>, cmd: &str) -> Self {
         Self {
-            context: context.map(ToOwned::to_owned),
+            context: diagnostic_context().or(context).map(ToOwned::to_owned),
             cmd: cmd.to_owned(),
             start_ts_us: now_us(),
             start: Instant::now(),
@@ -422,6 +458,23 @@ mod tests {
         CommandTrace::record_failed(None, "git nope", false, "precondition");
     }
 
+    #[test]
+    fn diagnostic_context_overrides_and_restores_command_context() {
+        let assert_context = |expected: &str| {
+            let mut trace = CommandTrace::new(Some("worktree"), "git status");
+            assert_eq!(trace.context(), Some(expected));
+            trace.complete(true);
+        };
+
+        assert_context("worktree");
+        with_diagnostic_context(|| {
+            assert_context(DIAGNOSTIC_CONTEXT);
+            with_diagnostic_context(|| assert_context(DIAGNOSTIC_CONTEXT));
+            assert_context(DIAGNOSTIC_CONTEXT);
+        });
+        assert_context("worktree");
+    }
+
     // A guard that reaches drop without complete()/fail() is a spawn site that
     // forgot to resolve its trace — the debug-build tripwire turns that into a
     // test failure rather than a silent unattributed gap.

src/trace/profile.rs

@@ -16,7 +16,9 @@
 //! - **Where is work wasted?** — [`CacheReport`] flags commands re-run with the
 //!   same context (a cache miss that should have been a hit). Commands that read
 //!   stdin are excluded — their real input isn't in the command string, so
-//!   identical command lines aren't necessarily identical work.
+//!   identical command lines aren't necessarily identical work. Subprocesses
+//!   that build the `-vv` diagnostic report are also excluded from every
+//!   aggregate; the raw trace retains them for debugging.
 //!
 //! The analysis ([`Profile::from_entries`], [`CacheReport::from_entries`]) is pure
 //! data over `&[TraceEntry]` and carries no styling, so it compiles without the
@@ -34,6 +36,7 @@ use serde::Serialize;
 
 use crate::styling::format_heading;
 
+use super::emit::DIAGNOSTIC_CONTEXT;
 use super::{TraceEntry, TraceEntryKind, TraceResult};
 
 /// How many individual calls [`Profile::slowest`] retains.
@@ -79,12 +82,12 @@ fn ser_opt_dur_us<S: serde::Serializer>(d: &Option<Duration>, s: S) -> Result<S:
 /// same fields, so the two views can't drift.
 #[derive(Debug, Clone, PartialEq, Serialize)]
 pub struct Profile {
-    /// First → last record, across commands, spans, and instant events.
+    /// First → last profiled record, across commands, spans, and instant events.
     #[serde(rename = "traced_us", serialize_with = "ser_dur_us")]
     pub traced: Duration,
-    /// Number of subprocess (command) records.
+    /// Number of profiled subprocess (command) records.
     pub command_count: usize,
-    /// Σ of every subprocess duration.
+    /// Σ of every profiled subprocess duration.
     #[serde(rename = "command_total_us", serialize_with = "ser_dur_us")]
     pub command_total: Duration,
     /// Σ of in-process span durations (config load, repo open, …).
@@ -96,7 +99,7 @@ pub struct Profile {
     pub parallelism: Option<f64>,
     /// Most subprocesses in flight simultaneously. `None` without timestamps.
     pub peak_concurrency: Option<usize>,
-    /// Distinct thread IDs that ran subprocesses.
+    /// Distinct thread IDs that ran profiled subprocesses.
     pub thread_count: usize,
     /// Derived `wt list` latencies from the collect milestones.
     pub key_intervals: KeyIntervals,
@@ -302,6 +305,17 @@ pub(super) fn command_label(command: &str, context: Option<&str>, result: &Trace
     label
 }
 
+/// Entries produced by the command being profiled.
+///
+/// The diagnostic collector runs after that command and appends to the same
+/// trace under a reserved context. Keeping the filter here makes every profile
+/// metric and the standalone cache report agree on the boundary.
+fn profile_entries(entries: &[TraceEntry]) -> impl Iterator<Item = &TraceEntry> {
+    entries
+        .iter()
+        .filter(|entry| entry.context.as_deref() != Some(DIAGNOSTIC_CONTEXT))
+}
+
 /// Microseconds of an entry's duration (zero for instant events).
 fn entry_dur_us(entry: &TraceEntry) -> u64 {
     match &entry.kind {
@@ -315,9 +329,10 @@ fn entry_dur_us(entry: &TraceEntry) -> u64 {
 impl Profile {
     /// Build a profile from parsed trace entries.
     pub fn from_entries(entries: &[TraceEntry]) -> Self {
-        let min_start = entries.iter().filter_map(|e| e.start_time_us).min();
-        let max_end = entries
-            .iter()
+        let min_start = profile_entries(entries)
+            .filter_map(|e| e.start_time_us)
+            .min();
+        let max_end = profile_entries(entries)
             .filter_map(|e| e.start_time_us.map(|s| s + entry_dur_us(e)))
             .max();
         let traced = match (min_start, max_end) {
@@ -335,7 +350,7 @@ impl Profile {
         let mut intervals: Vec<(u64, u64)> = Vec::new();
         let mut slowest: Vec<Slow> = Vec::new();
 
-        for entry in entries {
+        for entry in profile_entries(entries) {
             match &entry.kind {
                 TraceEntryKind::Command {
                     command,
@@ -409,8 +424,7 @@ impl Profile {
         let (parallelism, peak_concurrency) = concurrency(&intervals);
 
         let base = min_start.unwrap_or(0);
-        let mut milestones: Vec<(&str, u64)> = entries
-            .iter()
+        let mut milestones: Vec<(&str, u64)> = profile_entries(entries)
             .filter_map(|e| match &e.kind {
                 TraceEntryKind::Instant { name } => e.start_time_us.map(|s| (name.as_str(), s)),
                 _ => None,
@@ -676,7 +690,7 @@ impl CacheReport {
         // (command, context) → durations of every run, in microseconds.
         let mut pair_durations: HashMap<(&str, &str), Vec<u64>> = HashMap::new();
 
-        for entry in entries {
+        for entry in profile_entries(entries) {
             if let TraceEntryKind::Command {
                 command,
                 duration,

tests/integration_tests/diagnostic.rs

@@ -429,6 +429,52 @@ fn test_diagnostic_leads_with_profile(repo: TestRepo) {
     );
 }
 
+/// The subprocesses that assemble a `-vv` report stay visible in the raw trace
+/// but do not change any aggregate in the profile read back from that trace.
+#[rstest]
+fn test_profile_excludes_diagnostic_collector(repo: TestRepo) {
+    let output = repo.wt_command().args(["list", "-vv"]).output().unwrap();
+    assert!(
+        output.status.success(),
+        "wt list -vv should succeed: {}",
+        String::from_utf8_lossy(&output.stderr)
+    );
+
+    let logs_dir = repo.root_path().join(".git/wt/logs");
+    let trace_jsonl = fs::read_to_string(logs_dir.join("trace.jsonl")).unwrap();
+    let entries = worktrunk::trace::parse_lines(&trace_jsonl);
+    let diagnostic_context = worktrunk::trace::emit::DIAGNOSTIC_CONTEXT;
+    let profiled_entries: Vec<_> = entries
+        .iter()
+        .filter(|entry| entry.context.as_deref() != Some(diagnostic_context))
+        .cloned()
+        .collect();
+
+    assert!(
+        entries.iter().any(|entry| {
+            entry.context.as_deref() == Some(diagnostic_context)
+                && matches!(
+                    &entry.kind,
+                    worktrunk::trace::TraceEntryKind::Command { command, .. }
+                        if command == "git worktree list --porcelain"
+                )
+        }),
+        "the diagnostic collector should mark its worktree-list record:\n{trace_jsonl}"
+    );
+    assert_eq!(
+        worktrunk::trace::Profile::from_entries(&entries),
+        worktrunk::trace::Profile::from_entries(&profiled_entries)
+    );
+
+    let trace_log = fs::read_to_string(logs_dir.join("trace.log")).unwrap();
+    assert!(
+        trace_log
+            .lines()
+            .any(|line| line.contains("$ git worktree list --porcelain [(diagnostic)]")),
+        "the collector's command start and completion should share a context:\n{trace_log}"
+    );
+}
+
 /// At `-vv`, the full (uncapped) subprocess stdout/stderr should land in
 /// `subprocess.log` via `shell_exec::SUBPROCESS_FULL_TARGET` — not in `trace.log`.
 /// `trace.log` gets the bounded preview alongside trace records.