diff --git a/CLAUDE.md b/CLAUDE.md index d100f1c..3782bc4 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -59,7 +59,8 @@ PTY (ConPTY) → PseudoTerminal → TerminalBridge → WebView2 (xterm.js) | `StateService` | JSON persistence → `%AppData%/CodeShellManager/state.json`. Writes are **atomic**: serialize to `.tmp`, then `File.Replace` into place, rotating the previous file to `.bak`. `LoadAsync` falls back to `.bak` when the primary won't parse, and logs every step to `crash.log` rather than silently starting empty. A static `SemaphoreSlim` serializes saves — 29 of the ~32 `SaveStateAsync` call sites are fire-and-forget, and overlapping saves would otherwise race on the shared temp file. See issue #88. | | `SearchService` | SQLite FTS5 search of all terminal output; also owns the `project_notes` table | | `ColorService` | FNV-1a hash of folder path → 12-color palette | -| `GitService` | Async `git branch --show-current` + `git status --porcelain` | +| `GitService` | Async `git branch --show-current` + `git status --porcelain`. **Every await is `ConfigureAwait(false)` and `RunGitFullAsync` is `Task.Run`-wrapped — do not "simplify" either away.** See "Never spawn a process on the UI thread" below | +| `GitRepoWatcher` | `FileSystemWatcher` on a repo's `.git/HEAD` + `index`, debounced 400ms. Lets git state refresh on checkout/commit/stage instead of by polling. Resolves the `gitdir:` indirection so a linked worktree watches its own HEAD, not the main repo's. Returns null outside a repo — callers treat that as "poll only", not an error | | `AlertDetector` | Pattern matching for Claude prompts/approvals | | `CommandPresetsService` | Launch presets + in-session shortcuts | | `ClaudeSessionService` | Detects `claude` invocations; finds last `--resume` session id under `~/.claude/projects/` | @@ -135,6 +136,58 @@ tests/ The accent comes from the **live VM**, not the `Border.Tag` stashed at build time: `RepoRoot` is populated asynchronously by `GitService` and `AccentColor` changes when it lands, so a cached Tag goes stale and stops matching the sidebar ring. The Tag survives only as a fallback. `SetBorderColor` also assigns only when the colour actually differs — it previously allocated a fresh brush and reassigned every pane on every call, which was invisible at one call per switch and a visible flicker storm when something called it rapidly. +## Never spawn a process on the UI thread + +An `async` method runs everything **before its first `await` synchronously on the calling +thread**. `GitService.RunGitFullAsync` had `Process.Start` there, and the git poll chain +starts in `SessionViewModel`'s constructor — which `MainWindow.LaunchSessionAsync` runs on +the UI thread. The WPF `SynchronizationContext` was therefore captured, every continuation +returned to the UI thread, and git process creation happened *on* it. + +At 47 sessions polling every 10s that was ~94 synchronous `Process.Start` calls per cycle on +the UI thread. Traced live (issue #70): **42 UI stalls, worst 28.5s**, with foreground panes +accumulating output and flushing it in one blob — `dispatcher-latency=12781ms len=3350`. That +is the "I type and nothing appears, then it all appears at once" report. + +Measured on this hardware, and the numbers are the argument: + +| | | +|---|---| +| `cmd /c exit` | 21 ms — Windows baseline process creation | +| `git --version` | 42 ms — git startup, **zero** repo access | +| `git branch --show-current` | 41 ms — indistinguishable from doing nothing | +| `git status --porcelain` | 48–65 ms — only 6–23 ms of it is the tree walk | +| `Process.Start` alone | ~15 ms — the part that lands on the calling thread | + +**~85-90% of any git call is process startup, not git.** There is no faster query to switch +to, so the only fixes are to not be on the UI thread and to not spawn at all. + +Three rules, all load-bearing: + +1. **`GitService` must never depend on the caller's thread.** `RunGitFullAsync` is + `Task.Run`-wrapped so `Process.Start` cannot run inline, and every await is + `ConfigureAwait(false)` so no continuation can climb back. Both halves are needed: + `ConfigureAwait` alone would not have moved `Process.Start`. +2. **Long-lived loops started from the UI thread must be `Task.Run`-wrapped.** + `SessionViewModel`'s constructor does this for the git poll. A bare `_ = SomeAsync()` in a + constructor that runs on the UI thread silently pins the whole chain to it. +3. **Don't poll what you can watch.** `GitRepoWatcher` catches checkout/commit/stage + immediately; the poll only survives for working-tree edits, which dirty `status` without + touching `.git`. Foreground sessions poll at 10s, background at 120s, and switching to a + pane forces an immediate refresh via `SessionViewModel.IsForegroundSession`. + +Guarded by `tests/CodeShellManager.Tests/GitServiceThreadingTests.cs`, which calls +`GitService` from a thread whose `SynchronizationContext` never runs work: if any await +captures it the call never completes and the test times out. All three tests fail against +the pre-fix code — verify that still holds before trusting a change here. + +**`GitBranch` / `GitIsDirty` / `GitInfoLoaded` are hand-written properties, not +`[ObservableProperty]`.** They share one notification, `GitInfoVersion`, because three +generated setters meant three PropertyChanged events per poll per session — 141 sidebar +rebuilds per cycle at 47 sessions. `ApplyGitInfo` also returns early when the result is +unchanged, which is almost always: a branch changes maybe once an hour. Bind to +`GitInfoVersion`; the individual properties raise nothing of their own. + ## What makes a session "active" `MainViewModel.ActiveSession` drives the highlight, the dispatcher priority of terminal output (`TerminalBridge.IsForeground`, issue #70), and every `ActiveSession`-scoped command (`Ctrl+W`, `F5`, the run buttons). Three things set it: @@ -518,14 +571,49 @@ The tag value overrides the csproj `` at publish time (`-p:Version=` fl ```bash # 1. wait for CI / Release to finish and the GitHub Release to exist -# 2. then dispatch BOTH mirrors by hand +# 2. then dispatch the mirrors by hand gh workflow run winget.yml -f tag=vX.Y.Z -gh workflow run chocolatey.yml -f tag=vX.Y.Z -# 3. watch both — they fail independently of CI and nothing else will tell you +gh workflow run chocolatey.yml -f tag=vX.Y.Z # ONLY if not blocked — see below +# 3. watch them — they fail independently of CI and nothing else will tell you ``` To make it genuinely automatic, CI / Release would have to create the Release with a PAT rather than `GITHUB_TOKEN`. +**Chocolatey is currently blocked on moderation — do not dispatch it.** The v0.5.0 +submission is still awaiting *human* review on community.chocolatey.org. Automated +verification passes (last resubmission 03 Sep 2026, the #112 icon-CDN + WebView2 round), but +until a moderator approves it, newer versions cannot be submitted on top of it. Dispatching +`chocolatey.yml` for v0.6.0 or v0.7.0 does not queue them behind the review — it fails. + +Two consequences worth knowing before reading the numbers: + +- `community.chocolatey.org/packages/codeshellmanager` still serves **v0.5.0**, and will + keep doing so however many tags get pushed here. +- A package under moderation is not listed in search and cannot be installed without an + explicit `--version`, so its download counter reflects the moderation pipeline more than + it reflects users. + +Check the package page for the "awaiting moderation" banner before dispatching. Once it +clears, the backlog is submitted per tag. + +### Download counts: GitHub's number already contains the other two + +There is no per-channel breakdown, and it is easy to add the three up and get a wrong total. +Both mirrors resolve to **the GitHub Release MSI asset**: the winget manifest's +`InstallerUrl` points straight at it, and `.chocolatey/tools/chocolateyinstall.ps1` has its +`__URL64__` placeholder substituted with the same URL at pack time. + +So the MSI `download_count` on the GitHub Release is the **union** of GitHub-direct, winget +and Chocolatey installs — not the GitHub-only slice — and Chocolatey's own counter is a +subset of it, not an addition. It also includes the winget-pkgs validation pipeline's +download of each submitted MSI. + +Winget publishes no install statistics at all (Microsoft doesn't expose them, and the +unofficial `api.winget.run` index doesn't carry this package). Separating the channels would +mean publishing a byte-identical second MSI per release and pointing `winget.yml`'s +`installers-regex` at it — same SHA256, so winget-pkgs validation is unaffected — and that +only works going forward. + ### winget: the `CreateRef` error names the wrong culprit `winget.yml` submits the signed MSI to microsoft/winget-pkgs as `UmageAI.CodeShellManager` via [winget-releaser](https://github.com/vedantmgoyal9/winget-releaser). Needs `WINGET_TOKEN` — a **classic** PAT (fine-grained tokens are unsupported) with **both** `public_repo` and `workflow`. diff --git a/src/CodeShellManager/Assets/terminal-init.js b/src/CodeShellManager/Assets/terminal-init.js index 75e3ab7..86202f3 100644 --- a/src/CodeShellManager/Assets/terminal-init.js +++ b/src/CodeShellManager/Assets/terminal-init.js @@ -104,11 +104,49 @@ window.chrome.webview.postMessage(JSON.stringify({ type: 'resize', cols, rows })); }); + // ── Page-side diagnostics (issue #70) ────────────────────────────────────── + // The host's timing ends at PostWebMessageAsString. If the renderer process is the + // starved component — plausible at 25 panes, where 60+ WebView2 processes were measured + // — every host-side number reads healthy while typing still stalls. These two probes + // cover that blind spot. Off unless the host sends setDiag, and each reports only when + // it crosses a threshold, so a healthy session produces no traffic at all. + var diagOn = false; + var lastPaintProbeMs = 0; + + function diagReport(what, ms, len) { + try { + window.chrome.webview.postMessage(JSON.stringify({ + type: 'diag', what: what, ms: ms, len: len + })); + } catch (e) {} + } + + function diagWrite(data) { + if (!diagOn) { term.write(data); return; } + + var t0 = performance.now(); + term.write(data); + var t1 = performance.now(); + if (t1 - t0 > 50) diagReport('write-blocked', t1 - t0, data.length); + + // How long until the renderer actually produces a frame after this write. Sampled at + // most once a second: an rAF per output chunk across every pane would itself be load, + // and an instrument that changes the measurement is worth nothing here. + if (t1 - lastPaintProbeMs > 1000) { + lastPaintProbeMs = t1; + requestAnimationFrame(function () { + var lag = performance.now() - t1; + if (lag > 100) diagReport('paint-lag', lag, data.length); + }); + } + } + // ── Messages from WPF ────────────────────────────────────────────────────── window.chrome.webview.addEventListener('message', e => { try { const msg = JSON.parse(e.data); - if (msg.type === 'output') term.write(msg.data); + if (msg.type === 'output') diagWrite(msg.data); + else if (msg.type === 'setDiag') diagOn = !!msg.on; else if (msg.type === 'clear') term.clear(); else if (msg.type === 'focus') { term.focus(); fitAddon.fit(); } else if (msg.type === 'fit') { fitAddon.fit(); term.focus(); } diff --git a/src/CodeShellManager/Diagnostics/DiagnosticTrace.cs b/src/CodeShellManager/Diagnostics/DiagnosticTrace.cs new file mode 100644 index 0000000..ea301f4 --- /dev/null +++ b/src/CodeShellManager/Diagnostics/DiagnosticTrace.cs @@ -0,0 +1,137 @@ +using System; +using System.Collections.Concurrent; +using System.IO; +using System.Text; +using System.Threading; +using System.Threading.Tasks; + +namespace CodeShellManager.Diagnostics; + +/// +/// Buffered, non-blocking writer for [DEBUG-tt] diagnostic lines (issue #70). +/// +/// The original tracer called plus a synchronous +/// on every single trace call — on the PTY read thread for +/// output, and on the UI thread for the flush. That is fine for a two-session repro and +/// actively harmful at the ~25-session workload this issue is about: tracing the stall would +/// have added a file open/append/close to the very thread whose latency is being measured, +/// and the run would have measured the instrument. +/// +/// Callers enqueue a preformatted line and return immediately. A single background drain +/// writes batches to disk. Timestamps are taken at time, not at drain +/// time, so deferring the I/O does not distort the timings being recorded. +/// +public static class DiagnosticTrace +{ + // Bounded so a runaway session can't turn a diagnostic into an OOM. Dropped lines are + // counted and reported in-band, because a silent gap in a latency log is worse than + // no log at all — it reads as a stall that never happened. + private const int MaxQueued = 20000; + private const int DrainIntervalMs = 250; + + private static readonly ConcurrentQueue Queue = new(); + private static int _queued; + private static int _dropped; + private static int _started; + private static string? _path; + + /// + /// Mirrors AppSettings.DebugTerminalTrace for code that has no access to settings — + /// notably GitService, which is deliberately WPF-free and cannot reach the VM. + /// + public static bool Enabled; + + /// + /// Managed id of the WPF UI thread, stamped at startup. Lets a WPF-free service report + /// whether it is running on the UI thread without referencing a Dispatcher. + /// + public static int UiThreadId; + + /// True when the caller is executing on the UI thread. + public static bool OnUiThread => Environment.CurrentManagedThreadId == UiThreadId; + + /// Absolute path of the log being written. Resolved once, on first use. + public static string Path => _path ??= System.IO.Path.Combine( + Environment.GetFolderPath(Environment.SpecialFolder.ApplicationData), + "CodeShellManager", "crash.log"); + + /// + /// Points the writer at a scratch file and empties any queued state. Tests only — + /// the drain loop is a process-lifetime singleton, so tests drive + /// directly instead of racing it. + /// + internal static void ResetForTests(string path) + { + _path = path; + _started = 1; // suppress the background loop; tests pump DrainOnce themselves + while (Queue.TryDequeue(out _)) { } + Volatile.Write(ref _queued, 0); + Volatile.Write(ref _dropped, 0); + } + + /// + /// Queues one line. Safe from any thread, never touches the disk on the caller's thread. + /// The caller is expected to have already checked its trace flag. + /// + public static void Write(string tag, string? sessionId, string message) + { + if (Volatile.Read(ref _queued) >= MaxQueued) + { + Interlocked.Increment(ref _dropped); + return; + } + + Interlocked.Increment(ref _queued); + Queue.Enqueue($"[{DateTime.Now:HH:mm:ss.fff}] [{tag}] {sessionId ?? "?"} {message}"); + EnsureDrainStarted(); + } + + private static void EnsureDrainStarted() + { + if (Interlocked.CompareExchange(ref _started, 1, 0) != 0) return; + + try { Directory.CreateDirectory(System.IO.Path.GetDirectoryName(Path)!); } + catch { } + + // Long-running, so it gets its own thread rather than starving a pool thread that + // the PTY read path also wants. + _ = Task.Factory.StartNew(DrainLoop, TaskCreationOptions.LongRunning); + } + + private static void DrainLoop() + { + while (true) + { + Thread.Sleep(DrainIntervalMs); + DrainOnce(); + } + } + + /// Writes everything queued so far as one append. Returns the line count. + internal static int DrainOnce() + { + var sb = new StringBuilder(); + int lines = 0; + + while (Queue.TryDequeue(out string? line)) + { + Interlocked.Decrement(ref _queued); + sb.Append(line).Append('\n'); + lines++; + } + + int dropped = Interlocked.Exchange(ref _dropped, 0); + if (dropped > 0) + { + sb.Append($"[{DateTime.Now:HH:mm:ss.fff}] [DEBUG-tt] - " + + $"TRACE-OVERFLOW dropped={dropped} lines\n"); + lines++; + } + + if (sb.Length == 0) return 0; + + try { File.AppendAllText(Path, sb.ToString()); } + catch { } + return lines; + } +} diff --git a/src/CodeShellManager/Diagnostics/UiThreadHeartbeat.cs b/src/CodeShellManager/Diagnostics/UiThreadHeartbeat.cs new file mode 100644 index 0000000..744a7a0 --- /dev/null +++ b/src/CodeShellManager/Diagnostics/UiThreadHeartbeat.cs @@ -0,0 +1,80 @@ +using System; +using System.Windows.Threading; +using CodeShellManager.Models; + +namespace CodeShellManager.Diagnostics; + +/// +/// Measures UI-thread responsiveness independently of any terminal session (issue #70). +/// +/// A per-bridge dispatcher-latency figure cannot on its own distinguish "the whole UI +/// thread is saturated" from "this one bridge's batch was queued behind a big paint" — and +/// for background sessions it cannot distinguish either of those from ordinary +/// yielding, which is working as designed. +/// +/// This ticks at a fixed interval at and records how +/// late each tick actually ran. Overshoot here is UI-thread saturation, full stop, with no +/// session attribution needed. Correlating a typing stall against this timeline says whether +/// the pump was blocked at that moment or whether the delay lives somewhere else entirely. +/// +public sealed class UiThreadHeartbeat +{ + private const int IntervalMs = 250; + + // Only overshoot beyond this is logged. Timer resolution and ordinary paints produce a + // steady dribble of a few ms; logging those would bury the events that matter. + private const int ReportThresholdMs = 100; + + private readonly AppSettings _settings; + private readonly DispatcherTimer _timer; + private long _expectedNextMs; + private long _worstMs; + private int _overCount; + private long _lastSummaryMs; + + public UiThreadHeartbeat(AppSettings settings) + { + _settings = settings; + _timer = new DispatcherTimer(DispatcherPriority.Normal) + { + Interval = TimeSpan.FromMilliseconds(IntervalMs) + }; + _timer.Tick += OnTick; + } + + public void Start() + { + _expectedNextMs = Environment.TickCount64 + IntervalMs; + _lastSummaryMs = Environment.TickCount64; + _timer.Start(); + } + + public void Stop() => _timer.Stop(); + + private void OnTick(object? sender, EventArgs e) + { + long now = Environment.TickCount64; + long late = now - _expectedNextMs; + _expectedNextMs = now + IntervalMs; + + if (_settings.DebugTerminalTrace != true) return; + + if (late >= ReportThresholdMs) + { + _overCount++; + if (late > _worstMs) _worstMs = late; + DiagnosticTrace.Write("DEBUG-tt", "-", $"UI-STALL late={late}ms"); + } + + // A periodic summary so a log with no stall lines is still positive evidence that + // the pump was healthy, rather than ambiguous with "tracing wasn't on". + if (now - _lastSummaryMs >= 10000) + { + DiagnosticTrace.Write("DEBUG-tt", "-", + $"UI-HEARTBEAT window=10s stalls={_overCount} worst={_worstMs}ms"); + _lastSummaryMs = now; + _overCount = 0; + _worstMs = 0; + } + } +} diff --git a/src/CodeShellManager/MainWindow.xaml.cs b/src/CodeShellManager/MainWindow.xaml.cs index a28e71b..dc73f8a 100644 --- a/src/CodeShellManager/MainWindow.xaml.cs +++ b/src/CodeShellManager/MainWindow.xaml.cs @@ -204,6 +204,7 @@ private void SaveWindowBounds() /// Resolves PwshLocator.Executable off the UI thread; awaited before restore. private Task _pwshWarmup = Task.CompletedTask; + private Diagnostics.UiThreadHeartbeat? _uiHeartbeat; private async void OnLoaded(object sender, RoutedEventArgs e) { @@ -224,6 +225,16 @@ private async void OnLoaded(object sender, RoutedEventArgs e) RestoreWindowState(); _windowStateReady = true; + // Unattributed UI-thread latency baseline (issue #70). Started after settings load + // so it shares the live AppSettings ref and honours DebugTerminalTrace toggled at + // runtime; the timer itself is cheap enough to leave running either way. + _uiHeartbeat = new Diagnostics.UiThreadHeartbeat(_vm.Settings); + _uiHeartbeat.Start(); + + // Stamp the UI thread and mirror the trace flag for WPF-free services (GitService). + Diagnostics.DiagnosticTrace.UiThreadId = Environment.CurrentManagedThreadId; + Diagnostics.DiagnosticTrace.Enabled = _vm.Settings.DebugTerminalTrace; + // Build the group strip (it'll only show once there are groups + the setting is on). RebuildGroupStrip(); UpdateGroupStripVisibility(); @@ -1927,9 +1938,10 @@ static void UpdateGitText(TextBlock tb, SessionViewModel svm) ? Visibility.Visible : Visibility.Collapsed; break; - case nameof(SessionViewModel.GitBranch): - case nameof(SessionViewModel.GitIsDirty): - case nameof(SessionViewModel.GitInfoLoaded): + // One notification covers branch + dirty + loaded, however they were set + // (poll, OSC 9001, or folder edit). Previously three separate events + // rebuilt this row three times per poll (issue #70). + case nameof(SessionViewModel.GitInfoVersion): UpdateGitText(gitText, vm); UpdateWorktreeText(); break; @@ -2060,7 +2072,12 @@ private void UpdateActiveTerminalHighlight() // background session posts at Background priority and can't sit ahead of the // active pane's rendering or its keystrokes (issue #70). foreach (var s in _vm.Sessions) + { if (s.Bridge != null) s.Bridge.IsForeground = s.Id == activeId; + // Same signal drives git poll cadence: the visible pane polls every 10s, the + // rest back off to 2 minutes and rely on the .git watcher (issue #70). + s.IsForegroundSession = s.Id == activeId; + } foreach (var (id, ui) in _sessionUi) { @@ -5423,6 +5440,14 @@ private void SettingsButton_Click(object sender, RoutedEventArgs e) _vm.Settings.TerminalLetterSpacing = edited.TerminalLetterSpacing; _vm.Settings.TerminalLineHeight = edited.TerminalLineHeight; _vm.Settings.DebugTerminalTrace = edited.DebugTerminalTrace; + + // Bridges share the live AppSettings ref, so host-side tracing follows this + // automatically — but the page half is push-only and would stay dark on panes + // that are already running. Toggling the setting has to reach them (issue #70). + Diagnostics.DiagnosticTrace.Enabled = edited.DebugTerminalTrace; + foreach (var s in _vm.Sessions) + s.Bridge?.SetPageDiagnostics(edited.DebugTerminalTrace); + _ = _vm.SaveStateAsync(); // Push font settings to all active terminal sessions diff --git a/src/CodeShellManager/Services/GitRepoWatcher.cs b/src/CodeShellManager/Services/GitRepoWatcher.cs new file mode 100644 index 0000000..7c0a7a7 --- /dev/null +++ b/src/CodeShellManager/Services/GitRepoWatcher.cs @@ -0,0 +1,135 @@ +using System; +using System.IO; +using System.Threading; + +namespace CodeShellManager.Services; + +/// +/// Raises when a repo's HEAD or index is written — +/// i.e. on checkout, commit, merge, rebase, or staging (issue #70). +/// +/// This exists so git state can be refreshed on the events that change it instead of by +/// asking every ten seconds. Polling cost is dominated by process creation, not by git: +/// `git --version` measures 42ms against `branch --show-current` at 41ms, so each poll is +/// ~all overhead and there is no cheaper query to switch to. At 47 sessions that was ~94 +/// spawns per cycle to learn that nothing had changed. +/// +/// Deliberately NOT a substitute for polling: a plain working-tree edit makes +/// `status --porcelain` dirty without touching anything under .git. The watcher +/// covers git operations; a slow poll still covers dirtiness. See +/// SessionViewModel.PollGitInfoAsync. +/// +public sealed class GitRepoWatcher : IDisposable +{ + // Coalesces the burst a single git command produces — a checkout rewrites index and + // HEAD, and .NET reports lock/temp churn around both. + private const int DebounceMs = 400; + + private readonly FileSystemWatcher _watcher; + private readonly System.Threading.Timer _debounce; + private bool _disposed; + + /// Fired on a threadpool thread after the debounce window closes. + public event Action? Changed; + + private GitRepoWatcher(string gitDir) + { + _debounce = new System.Threading.Timer(_ => { if (!_disposed) Changed?.Invoke(); }, + null, Timeout.Infinite, Timeout.Infinite); + + _watcher = new FileSystemWatcher(gitDir) + { + // HEAD and index are both written as whole files (often via rename-over), so + // FileName has to be watched as well as LastWrite or a checkout can be missed. + NotifyFilter = NotifyFilters.LastWrite | NotifyFilters.FileName | NotifyFilters.Size, + IncludeSubdirectories = false + }; + + _watcher.Changed += OnAny; + _watcher.Created += OnAny; + _watcher.Renamed += OnAny; + _watcher.EnableRaisingEvents = true; + } + + /// + /// Creates a watcher for the repo containing , or null + /// if it isn't in a repo or the platform refuses the watch. Callers treat null as + /// "poll only" rather than an error — a session in a plain folder is perfectly valid. + /// + public static GitRepoWatcher? TryCreate(string workingFolder) + { + try + { + string? gitDir = ResolveGitDir(workingFolder); + if (gitDir == null || !Directory.Exists(gitDir)) return null; + return new GitRepoWatcher(gitDir); + } + catch + { + return null; + } + } + + /// + /// Walks up from looking for .git. A directory is + /// the ordinary case; a *file* means a linked worktree, and its gitdir: line + /// points at the per-worktree directory that actually holds that worktree's HEAD and + /// index. Watching the main repo's .git for a worktree session would report the wrong + /// branch entirely, so the indirection has to be followed. + /// + internal static string? ResolveGitDir(string startFolder) + { + if (string.IsNullOrWhiteSpace(startFolder)) return null; + + var dir = new DirectoryInfo(startFolder); + while (dir != null) + { + string candidate = Path.Combine(dir.FullName, ".git"); + + if (Directory.Exists(candidate)) return candidate; + + if (File.Exists(candidate)) + { + foreach (string line in File.ReadAllLines(candidate)) + { + if (!line.StartsWith("gitdir:", StringComparison.OrdinalIgnoreCase)) continue; + string target = line["gitdir:".Length..].Trim(); + if (target.Length == 0) return null; + return Path.IsPathRooted(target) + ? Path.GetFullPath(target) + : Path.GetFullPath(target, dir.FullName); + } + return null; + } + + dir = dir.Parent; + } + return null; + } + + private void OnAny(object sender, FileSystemEventArgs e) + { + if (_disposed) return; + + string name = e.Name ?? ""; + // Anything else under .git — objects, logs, config, packed-refs, lock files — either + // doesn't change what we display or is already implied by a HEAD/index write. + if (!name.Equals("HEAD", StringComparison.OrdinalIgnoreCase) + && !name.Equals("index", StringComparison.OrdinalIgnoreCase)) + return; + + try { _debounce.Change(DebounceMs, Timeout.Infinite); } catch (ObjectDisposedException) { } + } + + public void Dispose() + { + if (_disposed) return; + _disposed = true; + try { _watcher.EnableRaisingEvents = false; } catch { } + _watcher.Changed -= OnAny; + _watcher.Created -= OnAny; + _watcher.Renamed -= OnAny; + _watcher.Dispose(); + _debounce.Dispose(); + } +} diff --git a/src/CodeShellManager/Services/GitService.cs b/src/CodeShellManager/Services/GitService.cs index b8b7ac0..0723968 100644 --- a/src/CodeShellManager/Services/GitService.cs +++ b/src/CodeShellManager/Services/GitService.cs @@ -16,11 +16,11 @@ public static class GitService try { - string? branch = await RunGitAsync(folderPath, "branch --show-current"); + string? branch = await RunGitAsync(folderPath, "branch --show-current").ConfigureAwait(false); if (string.IsNullOrWhiteSpace(branch)) return (null, false); - string? statusOutput = await RunGitAsync(folderPath, "status --porcelain"); + string? statusOutput = await RunGitAsync(folderPath, "status --porcelain").ConfigureAwait(false); bool isDirty = !string.IsNullOrWhiteSpace(statusOutput); return (branch.Trim(), isDirty); @@ -45,7 +45,7 @@ public static class GitService return null; try { - string? commonDir = await RunGitAsync(folderPath, "rev-parse --git-common-dir"); + string? commonDir = await RunGitAsync(folderPath, "rev-parse --git-common-dir").ConfigureAwait(false); if (string.IsNullOrWhiteSpace(commonDir)) return null; string trimmed = commonDir.Trim(); @@ -82,7 +82,7 @@ public static async Task> ListWorktreesAsync(string return Array.Empty(); try { - string? raw = await RunGitAsync(folderPath, "worktree list --porcelain"); + string? raw = await RunGitAsync(folderPath, "worktree list --porcelain").ConfigureAwait(false); if (string.IsNullOrWhiteSpace(raw)) return Array.Empty(); // Output is blank-line separated stanzas: @@ -125,7 +125,7 @@ public static async Task> ListBranchesAsync(string folderP return Array.Empty(); try { - string? raw = await RunGitAsync(folderPath, "for-each-ref --format=%(refname:short) refs/heads"); + string? raw = await RunGitAsync(folderPath, "for-each-ref --format=%(refname:short) refs/heads").ConfigureAwait(false); if (string.IsNullOrWhiteSpace(raw)) return Array.Empty(); var lines = raw.Replace("\r", "").Split('\n', StringSplitOptions.RemoveEmptyEntries); return lines; @@ -151,7 +151,7 @@ public static async Task> ListBranchesAsync(string folderP ? $"worktree add -b \"{branchOrRef}\" \"{targetPath}\"" : $"worktree add \"{targetPath}\" \"{branchOrRef}\""; - var (output, stderr, exit) = await RunGitFullAsync(repoRoot, args, timeoutMs: 30_000); + var (output, stderr, exit) = await RunGitFullAsync(repoRoot, args, timeoutMs: 30_000).ConfigureAwait(false); if (exit == 0) return (true, ""); string err = string.IsNullOrWhiteSpace(stderr) ? (string.IsNullOrWhiteSpace(output) ? "git worktree add failed." : output) @@ -161,11 +161,19 @@ public static async Task> ListBranchesAsync(string folderP private static async Task RunGitAsync(string workingDir, string arguments) { - var (stdout, _, exit) = await RunGitFullAsync(workingDir, arguments, timeoutMs: 3000); + var (stdout, _, exit) = await RunGitFullAsync(workingDir, arguments, timeoutMs: 3000).ConfigureAwait(false); return exit == 0 ? stdout : null; } - private static async Task<(string stdout, string stderr, int exit)> RunGitFullAsync( + /// + /// Runs one git command. The body is wrapped in deliberately — + /// see the note on Process.Start below (issue #70). + /// + private static Task<(string stdout, string stderr, int exit)> RunGitFullAsync( + string workingDir, string arguments, int timeoutMs) + => Task.Run(() => RunGitCoreAsync(workingDir, arguments, timeoutMs)); + + private static async Task<(string stdout, string stderr, int exit)> RunGitCoreAsync( string workingDir, string arguments, int timeoutMs) { // WSL working folders (\\wsl$\\…) get routed through wsl.exe so git @@ -184,19 +192,42 @@ public static async Task> ListBranchesAsync(string folderP CreateNoWindow = true }; + // Process.Start is synchronous and sits BEFORE this method's first await, so without + // the Task.Run above it ran on whatever thread called in. Every caller chain here + // starts in SessionViewModel's constructor on the UI thread, so its + // SynchronizationContext was captured, every continuation returned there, and + // process creation landed on the UI thread — 94 spawns per 10s poll at 47 sessions. + // + // Measured on an idle machine: Process.Start alone is ~15ms (9-20ms), so that was + // ~1.4s of hard UI-thread block per cycle before contention, which is what produced + // the multi-second typing freezes traced in issue #70. Note the cost is almost + // entirely process creation, not git: `git --version` measures 42ms against + // `branch --show-current` at 41ms, so there is no faster query to switch to. + // + // Every await below is ConfigureAwait(false) so no continuation can climb back onto + // the UI thread even if a future caller invokes this from there directly. + bool onUi = Diagnostics.DiagnosticTrace.OnUiThread; + long spawnStart = Environment.TickCount64; + using var process = Process.Start(psi); + + if (Diagnostics.DiagnosticTrace.Enabled) + Diagnostics.DiagnosticTrace.Write("DEBUG-tt", "git", + $"GIT-SPAWN on-ui={onUi} spawn={Environment.TickCount64 - spawnStart}ms " + + $"args='{arguments}'"); + if (process is null) return ("", "", -1); var outTask = process.StandardOutput.ReadToEndAsync(); var errTask = process.StandardError.ReadToEndAsync(); var bothTask = Task.WhenAll(outTask, errTask); - var completed = await Task.WhenAny(bothTask, Task.Delay(timeoutMs)); + var completed = await Task.WhenAny(bothTask, Task.Delay(timeoutMs)).ConfigureAwait(false); if (completed != bothTask) { try { process.Kill(); } catch { } } - try { await process.WaitForExitAsync(); } catch { } + try { await process.WaitForExitAsync().ConfigureAwait(false); } catch { } string stdout = outTask.IsCompletedSuccessfully ? outTask.Result : ""; string stderr = errTask.IsCompletedSuccessfully ? errTask.Result : ""; diff --git a/src/CodeShellManager/Terminal/TerminalBridge.cs b/src/CodeShellManager/Terminal/TerminalBridge.cs index ce1cf4b..653c262 100644 --- a/src/CodeShellManager/Terminal/TerminalBridge.cs +++ b/src/CodeShellManager/Terminal/TerminalBridge.cs @@ -54,6 +54,15 @@ public sealed class TerminalBridge : IDisposable public string? DebugSessionId { get; set; } private long _lastOutputTickMs; + // Set when a coalesced flush is queued, read when it runs, so the gap between the two + // is the dispatcher queue latency — the number that says whether the UI pump is the + // bottleneck. OutputCoalescer guarantees at most one flush in flight per bridge, so a + // single field is sufficient. Restored here after 71e1294 removed the original along + // with the per-chunk post it was attached to (issue #70). + private long _flushEnqueuedAtMs; + private bool _flushQueuedAsForeground; + private long _lastInputTickMs; + public event Action? RawOutputReceived; /// @@ -114,19 +123,14 @@ private static void Log(string msg) catch { } } + // Queues the line; the disk write happens on a background drain. This used to open, + // append to and close crash.log inline on whichever thread was tracing — the PTY reader + // for output, the UI thread for the flush. At the session count this issue reproduces + // at, that made the tracer a cause of the latency it was measuring (issue #70). private void Trace(string msg) { if (DebugSettings?.DebugTerminalTrace != true) return; - try - { - string path = System.IO.Path.Combine( - System.Environment.GetFolderPath(System.Environment.SpecialFolder.ApplicationData), - "CodeShellManager", "crash.log"); - System.IO.Directory.CreateDirectory(System.IO.Path.GetDirectoryName(path)!); - System.IO.File.AppendAllText(path, - $"[{DateTime.Now:HH:mm:ss.fff}] [DEBUG-tt] {DebugSessionId ?? "?"} {msg}\n"); - } - catch { } + Diagnostics.DiagnosticTrace.Write("DEBUG-tt", DebugSessionId, msg); } // Posts a one-shot bootDone message to the WebView2. Safe to call from any thread. @@ -152,8 +156,20 @@ private void ScheduleFlush(Action flush) { var dispatcher = WpfApplication.Current?.Dispatcher; if (dispatcher == null) return; + + // Read once, so the priority recorded in the trace is provably the one used for + // the post. IsForeground is written from the UI thread while this runs on the PTY + // thread, and a stale read here is itself a candidate explanation for the stall. + bool foreground = IsForeground; + + if (DebugSettings?.DebugTerminalTrace == true) + { + System.Threading.Volatile.Write(ref _flushEnqueuedAtMs, Environment.TickCount64); + _flushQueuedAsForeground = foreground; + } + dispatcher.BeginInvoke( - IsForeground + foreground ? System.Windows.Threading.DispatcherPriority.Normal : System.Windows.Threading.DispatcherPriority.Background, flush); @@ -162,11 +178,47 @@ private void ScheduleFlush(Action flush) // Runs on the UI thread. One WebView2 post per coalesced batch. private void PostOutput(string data) { + bool tracing = DebugSettings?.DebugTerminalTrace == true; + long enqueuedAt = tracing + ? System.Threading.Interlocked.Exchange(ref _flushEnqueuedAtMs, 0) + : 0; + string json = JsonSerializer.Serialize(new { type = "output", data }); try { _webView.CoreWebView2?.PostWebMessageAsString(json); } catch { } - if (DebugSettings?.DebugTerminalTrace == true) - Trace($"OUTPUT flush len={data.Length}"); + + if (!tracing) return; + + long now = Environment.TickCount64; + long lastInput = System.Threading.Volatile.Read(ref _lastInputTickMs); + + // dispatcher-latency: queued on the PTY thread -> ran on the UI thread. Large values + // mean the UI pump is the bottleneck. Read it together with prio: for a bg batch a + // large value may just be Background priority yielding correctly, which is why the + // UI-STALL heartbeat is logged separately and unattributed. + // since-input: how long before this batch the user last typed. When a stall is + // reported, this is what ties a late flush to the keystroke it failed to echo. + Trace($"OUTPUT flush len={data.Length} " + + $"dispatcher-latency={(enqueuedAt == 0 ? -1 : now - enqueuedAt)}ms " + + $"prio={(_flushQueuedAsForeground ? "fg" : "bg")} " + + $"since-input={(lastInput == 0 ? -1 : now - lastInput)}ms"); + } + + /// + /// Turns page-side timing probes on or off for a pane that is already running. + /// Without this, toggling the trace setting mid-session would enable the host-side + /// numbers while the page half stayed dark — and the renderer is exactly the component + /// the host cannot see (issue #70). + /// + public void SetPageDiagnostics(bool on) + { + if (!_ready) return; // NavigationCompleted posts the initial state itself + try + { + _webView.CoreWebView2?.PostWebMessageAsString( + JsonSerializer.Serialize(new { type = "setDiag", on })); + } + catch { } } /// @@ -257,6 +309,19 @@ void NavCompleted(object? s, CoreWebView2NavigationCompletedEventArgs e) catch { } } + // Turn on page-side timing when tracing is enabled. The host cannot see past + // PostWebMessageAsString: if the renderer process is the thing that's starved, + // every host-side number looks healthy and the stall is still real (issue #70). + if (DebugSettings?.DebugTerminalTrace == true) + { + try + { + _webView.CoreWebView2?.PostWebMessageAsString( + JsonSerializer.Serialize(new { type = "setDiag", on = true })); + } + catch { } + } + // Silent-session fallback: if the child writes nothing (or exits without // any output) the overlay would otherwise block the terminal indefinitely. // PostBootDoneIfNeeded is idempotent via Interlocked, so this is a no-op @@ -348,6 +413,7 @@ private void OnWebMessageReceived(object? sender, CoreWebView2WebMessageReceived if (DebugSettings?.DebugTerminalTrace == true) { long t0 = Environment.TickCount64; + System.Threading.Volatile.Write(ref _lastInputTickMs, t0); Trace($"INPUT len={data.Length}"); _pty?.Write(data); Trace($"PTY-WROTE elapsed={Environment.TickCount64 - t0}ms"); @@ -373,6 +439,20 @@ private void OnWebMessageReceived(object? sender, CoreWebView2WebMessageReceived PaneActivated?.Invoke(); break; + // Page-side timing, only sent while setDiag is on and only when a threshold + // is crossed — see terminal-init.js. Reports what happens after the host's + // last visibility point: how long term.write blocked, and how long the + // renderer then took to produce a frame. + case "diag": + { + if (DebugSettings?.DebugTerminalTrace != true) break; + string what = root.TryGetProperty("what", out var w) ? w.GetString() ?? "?" : "?"; + double ms = root.TryGetProperty("ms", out var m) ? m.GetDouble() : -1; + int len = root.TryGetProperty("len", out var l) ? l.GetInt32() : -1; + Trace($"PAGE {what}={ms:0}ms len={len}"); + break; + } + case "resize": { int cols = root.GetProperty("cols").GetInt32(); diff --git a/src/CodeShellManager/ViewModels/SessionViewModel.cs b/src/CodeShellManager/ViewModels/SessionViewModel.cs index 14ca23f..7f65b07 100644 --- a/src/CodeShellManager/ViewModels/SessionViewModel.cs +++ b/src/CodeShellManager/ViewModels/SessionViewModel.cs @@ -18,9 +18,29 @@ public partial class SessionViewModel : ObservableObject, IDisposable [ObservableProperty] private bool _isActive; [ObservableProperty] private bool _isWaitingForInput; [ObservableProperty] private bool _isWaitingForApproval; - [ObservableProperty] private string? _gitBranch; - [ObservableProperty] private bool _gitIsDirty; - [ObservableProperty] private bool _gitInfoLoaded; + // Hand-written rather than [ObservableProperty] so all three share ONE change + // notification, GitInfoVersion. As generated properties they raised three events per + // poll per session — 141 sidebar rebuilds per cycle at 47 sessions (issue #70). + private string? _gitBranch; + public string? GitBranch + { + get => _gitBranch; + set { if (_gitBranch != value) { _gitBranch = value; BumpGitInfo(); } } + } + + private bool _gitIsDirty; + public bool GitIsDirty + { + get => _gitIsDirty; + set { if (_gitIsDirty != value) { _gitIsDirty = value; BumpGitInfo(); } } + } + + private bool _gitInfoLoaded; + public bool GitInfoLoaded + { + get => _gitInfoLoaded; + set { if (_gitInfoLoaded != value) { _gitInfoLoaded = value; BumpGitInfo(); } } + } /// Absolute path to the session's repo top-level, or null if the working folder is not in a git repo. [ObservableProperty] private string? _repoRoot; /// Set by MainWindow whenever another live session shares this session's RepoRoot. @@ -73,16 +93,38 @@ public SessionViewModel(ShellSession session) { Session = session; Runner = new SessionRunner(session); + + // Captured here, on the UI thread, so the watcher callback (which fires on a + // threadpool thread) can hop back before touching properties. + _uiContext = SynchronizationContext.Current; + + // These intentionally keep the UI context: RefreshGitInfoAsync pushes the actual + // probe off-thread itself and resumes here to set properties. What made this + // dangerous before was GitService running Process.Start on whichever thread called + // in — fixed inside GitService, so capturing the context is safe again (issue #70). _ = RefreshGitInfoAsync(); _ = PollGitInfoAsync(_gitPollCts.Token); + StartGitWatcher(); } /// - /// Git poll cadence per kind. WSL probes spawn wsl.exe (much heavier than a local git - /// spawn) and defeat WSL2's idle-VM shutdown, so they run a third as often. + /// Git poll cadence, by kind and by whether the pane is the one on screen. + /// + /// Kind: WSL probes spawn wsl.exe (much heavier than a local git spawn) and defeat + /// WSL2's idle-VM shutdown, so they run a third as often. + /// + /// Foreground: everything you are not looking at backs off hard. A poll is ~all process + /// creation — `git --version` costs 42ms against `branch --show-current` at 41ms — so + /// 46 background sessions polling every 10s was pure overhead to learn nothing had + /// changed. Real git operations still arrive immediately via ; + /// the slow poll only has to catch working-tree edits, which dirty `status` without + /// touching anything under .git (issue #70). /// - internal static TimeSpan GitPollIntervalFor(SessionKind kind) => - kind == SessionKind.Wsl ? TimeSpan.FromSeconds(30) : TimeSpan.FromSeconds(10); + internal static TimeSpan GitPollIntervalFor(SessionKind kind, bool isForeground) + { + if (!isForeground) return TimeSpan.FromSeconds(120); + return kind == SessionKind.Wsl ? TimeSpan.FromSeconds(30) : TimeSpan.FromSeconds(10); + } // WSL only: a "not a repo" answer costs a wsl.exe spawn per tick, so remember it. // Local folders keep re-probing (a `git init` should be picked up within a tick). @@ -103,14 +145,17 @@ public async Task RefreshGitInfoAsync() var token = _gitPollCts.Token; // Off the dispatcher: GitService begins with a synchronous Directory.Exists, and on - // a \\wsl$ share that boots a stopped distro (seconds). Continuations return to the - // captured UI context, so the property sets below stay on the UI thread. + // a \\wsl$ share that boots a stopped distro (seconds). + // + // Deliberately NOT ConfigureAwait(false): when a caller has a UI context, the + // property sets below resume on it. GitService is separately hardened so no git + // work can run on the caller's thread regardless (issue #70) — this Task.Run covers + // the synchronous Directory.Exists prefix that sits outside it, and keeping the + // resume on the UI thread is what lets the sets below notify WPF safely. string folder = Session.WorkingFolder; var (branch, isDirty) = await Task.Run(() => GitService.GetGitInfoAsync(folder)); if (token.IsCancellationRequested) return; // session closed while the probe was off-thread - GitBranch = branch; - GitIsDirty = isDirty; - GitInfoLoaded = true; + ApplyGitInfo(branch, isDirty); // RepoRoot is stable for the life of the session — resolve it once. Don't gate on // a non-empty branch: detached HEADs report no branch but are still valid repos @@ -124,6 +169,92 @@ public async Task RefreshGitInfoAsync() } } + /// + /// Applies a git poll result as ONE change notification instead of three (issue #70). + /// + /// GitBranch, GitIsDirty and GitInfoLoaded are three [ObservableProperty] writes, + /// so every poll raised three PropertyChanged events per session, each crossing a + /// blocking Dispatcher.Invoke and rebuilding the sidebar row's WPF inlines — 141 rebuilds + /// per cycle at 47 sessions, to redraw text that almost never differs. + /// + /// The early-out matters more than the coalescing: a branch changes maybe once an hour, + /// so the overwhelmingly common poll result is "identical to last time", and that now + /// costs no UI work at all. + /// + public void ApplyGitInfo(string? branch, bool isDirty) + { + if (_gitInfoLoaded && _gitBranch == branch && _gitIsDirty == isDirty) return; + + // Backing fields directly — the generated setters would raise one event each. + _gitBranch = branch; + _gitIsDirty = isDirty; + _gitInfoLoaded = true; + + BumpGitInfo(); + } + + /// + /// The single change notification for git state. Watch this rather than GitBranch / + /// GitIsDirty / GitInfoLoaded, none of which raise events of their own. + /// + public int GitInfoVersion => _gitInfoVersion; + private int _gitInfoVersion; + + private void BumpGitInfo() + { + _gitInfoVersion++; + OnPropertyChanged(nameof(GitInfoVersion)); + } + + /// + /// True while this session's pane is the active one. Set by MainWindow alongside + /// TerminalBridge.IsForeground. Governs poll cadence, and forces an immediate + /// refresh on activation so switching to a pane shows current git state at once rather + /// than up to later. + /// + public bool IsForegroundSession + { + get => _isForegroundSession; + set + { + if (_isForegroundSession == value) return; + _isForegroundSession = value; + if (value) _ = Task.Run(() => RefreshGitInfoAsync()); + } + } + private bool _isForegroundSession; + + // The pane you're looking at keeps the old cadence. Everything else backs off hard: the + // watcher catches real git operations immediately, so this slow poll only has to catch + // working-tree edits that dirty the tree without touching anything under .git. + private const int ForegroundPollMs = 10_000; + private const int BackgroundPollMs = 120_000; + + private GitRepoWatcher? _gitWatcher; + private readonly SynchronizationContext? _uiContext; + + private void StartGitWatcher() + { + // Local only. SSH has no local filesystem, and a WSL session's folder is a + // `\\wsl$\...` UNC — watching that keeps the distro's 9p server busy and defeats + // the idle-VM shutdown the WSL cadence above exists to protect. + if (Session.Kind != SessionKind.Local) return; + _gitWatcher = GitRepoWatcher.TryCreate(Session.WorkingFolder); + if (_gitWatcher != null) _gitWatcher.Changed += OnGitDirChanged; + // null is normal: a plain folder, or a platform that refused the watch. Poll only. + } + + private void OnGitDirChanged() + { + if (_gitPollCts.IsCancellationRequested) return; + + // The watcher fires on a threadpool thread. Hop back to the context this VM was + // created on so RefreshGitInfoAsync's property sets land on the UI thread, exactly + // as they do on the poll path. + if (_uiContext != null) _uiContext.Post(_ => { _ = RefreshGitInfoAsync(); }, null); + else _ = RefreshGitInfoAsync(); + } + /// Short repo + branch label shown beneath the session name when sibling worktrees are open. public string WorktreeSubtitle { @@ -138,11 +269,16 @@ public string WorktreeSubtitle private async Task PollGitInfoAsync(CancellationToken ct) { - using var timer = new PeriodicTimer(GitPollIntervalFor(Session.Kind)); try { - while (await timer.WaitForNextTickAsync(ct)) + while (!ct.IsCancellationRequested) + { + // Interval is recomputed each iteration rather than fixed by a PeriodicTimer, + // so promoting a session to the foreground speeds up its next poll without + // restarting the loop. + await Task.Delay(GitPollIntervalFor(Session.Kind, IsForegroundSession), ct); await RefreshGitInfoAsync(); + } } catch (OperationCanceledException) { } } @@ -270,6 +406,12 @@ public void Dispose() Runner.Dispose(); _gitPollCts.Cancel(); _gitPollCts.Dispose(); + if (_gitWatcher != null) + { + _gitWatcher.Changed -= OnGitDirChanged; + _gitWatcher.Dispose(); + _gitWatcher = null; + } AlertDetector?.Dispose(); OutputIndexer?.Dispose(); Bridge?.Dispose(); diff --git a/tests/CodeShellManager.Tests/DiagnosticTraceCollection.cs b/tests/CodeShellManager.Tests/DiagnosticTraceCollection.cs new file mode 100644 index 0000000..13fc68b --- /dev/null +++ b/tests/CodeShellManager.Tests/DiagnosticTraceCollection.cs @@ -0,0 +1,10 @@ +using Xunit; + +namespace CodeShellManager.Tests; + +/// +/// DiagnosticTrace is process-wide static state (log path, Enabled, UiThreadId). Tests that +/// touch it must not run concurrently with each other or they clobber one another's setup. +/// +[CollectionDefinition("DiagnosticTrace", DisableParallelization = true)] +public class DiagnosticTraceCollection { } diff --git a/tests/CodeShellManager.Tests/DiagnosticTraceTests.cs b/tests/CodeShellManager.Tests/DiagnosticTraceTests.cs new file mode 100644 index 0000000..28d5381 --- /dev/null +++ b/tests/CodeShellManager.Tests/DiagnosticTraceTests.cs @@ -0,0 +1,88 @@ +using System; +using System.IO; +using CodeShellManager.Diagnostics; +using Xunit; + +namespace CodeShellManager.Tests; + +/// +/// The tracer for issue #70 exists to measure a latency problem, so the one failure mode +/// that matters is it silently writing nothing — a traced session at the real workload is +/// expensive to arrange, and an empty log is indistinguishable from "the bug didn't happen". +/// +[Collection("DiagnosticTrace")] +public class DiagnosticTraceTests : IDisposable +{ + private readonly string _path = Path.Combine( + Path.GetTempPath(), $"csm-trace-{Guid.NewGuid():N}.log"); + + public DiagnosticTraceTests() => DiagnosticTrace.ResetForTests(_path); + + public void Dispose() + { + try { if (File.Exists(_path)) File.Delete(_path); } catch { } + } + + [Fact] + public void Write_then_drain_puts_the_line_in_the_file() + { + DiagnosticTrace.Write("DEBUG-tt", "abc12345", "OUTPUT flush len=42 dispatcher-latency=1730ms"); + + Assert.Equal(1, DiagnosticTrace.DrainOnce()); + + string content = File.ReadAllText(_path); + Assert.Contains("[DEBUG-tt]", content); + Assert.Contains("abc12345", content); + Assert.Contains("dispatcher-latency=1730ms", content); + } + + [Fact] + public void Lines_are_written_in_order() + { + for (int i = 0; i < 50; i++) + DiagnosticTrace.Write("DEBUG-tt", "s", $"line={i}"); + + DiagnosticTrace.DrainOnce(); + + string[] lines = File.ReadAllLines(_path); + Assert.Equal(50, lines.Length); + Assert.Contains("line=0", lines[0]); + Assert.Contains("line=49", lines[49]); + } + + [Fact] + public void Nothing_queued_writes_no_file() + { + Assert.Equal(0, DiagnosticTrace.DrainOnce()); + Assert.False(File.Exists(_path)); + } + + [Fact] + public void Overflow_is_reported_in_band_rather_than_leaving_a_silent_gap() + { + // A dropped line in a latency log reads as a stall that never happened, so the + // drop count has to appear in the log itself. + for (int i = 0; i < 20050; i++) + DiagnosticTrace.Write("DEBUG-tt", "s", $"line={i}"); + + DiagnosticTrace.DrainOnce(); + + string content = File.ReadAllText(_path); + Assert.Contains("TRACE-OVERFLOW dropped=", content); + } + + [Fact] + public void Missing_session_id_falls_back_to_the_existing_question_mark_convention() + { + // TerminalBridge.Trace has always written "?" for an unset session id; unattributed + // lines (the heartbeat, overflow) pass "-" explicitly. Both must stay greppable. + DiagnosticTrace.Write("DEBUG-tt", null, "UI-STALL late=1200ms"); + DiagnosticTrace.Write("DEBUG-tt", "-", "UI-HEARTBEAT window=10s stalls=0 worst=0ms"); + + DiagnosticTrace.DrainOnce(); + + string content = File.ReadAllText(_path); + Assert.Contains("[DEBUG-tt] ? UI-STALL late=1200ms", content); + Assert.Contains("[DEBUG-tt] - UI-HEARTBEAT", content); + } +} diff --git a/tests/CodeShellManager.Tests/GitRepoWatcherTests.cs b/tests/CodeShellManager.Tests/GitRepoWatcherTests.cs new file mode 100644 index 0000000..29edf44 --- /dev/null +++ b/tests/CodeShellManager.Tests/GitRepoWatcherTests.cs @@ -0,0 +1,161 @@ +using System; +using System.IO; +using System.Threading; +using CodeShellManager.Services; +using Xunit; + +namespace CodeShellManager.Tests; + +/// +/// Tests for the .git watcher that replaces most of the 10s poll (issue #70). +/// +public class GitRepoWatcherTests : IDisposable +{ + private readonly string _root = Path.Combine( + Path.GetTempPath(), $"csm-gitwatch-{Guid.NewGuid():N}"); + + public GitRepoWatcherTests() => Directory.CreateDirectory(_root); + + public void Dispose() + { + try { Directory.Delete(_root, recursive: true); } catch { } + } + + private string MakeRepo(string name) + { + string work = Path.Combine(_root, name); + Directory.CreateDirectory(Path.Combine(work, ".git")); + File.WriteAllText(Path.Combine(work, ".git", "HEAD"), "ref: refs/heads/main\n"); + return work; + } + + [Fact] + public void ResolveGitDir_finds_a_plain_repo() + { + string work = MakeRepo("plain"); + Assert.Equal(Path.Combine(work, ".git"), GitRepoWatcher.ResolveGitDir(work)); + } + + [Fact] + public void ResolveGitDir_walks_up_from_a_subfolder() + { + string work = MakeRepo("nested"); + string deep = Path.Combine(work, "src", "a", "b"); + Directory.CreateDirectory(deep); + + Assert.Equal(Path.Combine(work, ".git"), GitRepoWatcher.ResolveGitDir(deep)); + } + + [Fact] + public void ResolveGitDir_follows_a_worktree_gitdir_file() + { + // A linked worktree has .git as a FILE pointing at the per-worktree directory. + // Watching the main repo's .git instead would report the wrong branch for that + // session entirely, so this indirection has to be followed. + string main = MakeRepo("main"); + string wtGitDir = Path.Combine(main, ".git", "worktrees", "feature"); + Directory.CreateDirectory(wtGitDir); + File.WriteAllText(Path.Combine(wtGitDir, "HEAD"), "ref: refs/heads/feature\n"); + + string wt = Path.Combine(_root, "feature-wt"); + Directory.CreateDirectory(wt); + File.WriteAllText(Path.Combine(wt, ".git"), $"gitdir: {wtGitDir}\n"); + + Assert.Equal(wtGitDir, GitRepoWatcher.ResolveGitDir(wt)); + } + + [Fact] + public void ResolveGitDir_returns_null_outside_a_repo() + { + string plain = Path.Combine(_root, "not-a-repo"); + Directory.CreateDirectory(plain); + + // Temp itself must not be inside a repo for this to be meaningful. + Assert.Null(GitRepoWatcher.ResolveGitDir(plain)); + } + + [Fact] + public void TryCreate_returns_null_outside_a_repo_rather_than_throwing() + { + // Callers treat null as "poll only". A session in a plain folder is valid, not an error. + string plain = Path.Combine(_root, "plain-folder"); + Directory.CreateDirectory(plain); + + Assert.Null(GitRepoWatcher.TryCreate(plain)); + } + + [Fact] + public void Writing_HEAD_raises_Changed() + { + string work = MakeRepo("head-change"); + using var watcher = GitRepoWatcher.TryCreate(work); + Assert.NotNull(watcher); + + using var fired = new ManualResetEventSlim(false); + watcher!.Changed += () => fired.Set(); + + File.WriteAllText(Path.Combine(work, ".git", "HEAD"), "ref: refs/heads/other\n"); + + Assert.True(fired.Wait(TimeSpan.FromSeconds(10)), + "a HEAD write must refresh git state — that is the branch-switch case the " + + "watcher exists to catch without polling"); + } + + [Fact] + public void Writing_an_unrelated_file_under_git_does_not_raise_Changed() + { + // The point of the watcher is to stop spawning git when nothing relevant happened. + // If object/log churn woke it, it would reintroduce the cost it was built to remove. + string work = MakeRepo("noise"); + using var watcher = GitRepoWatcher.TryCreate(work); + Assert.NotNull(watcher); + + using var fired = new ManualResetEventSlim(false); + watcher!.Changed += () => fired.Set(); + + File.WriteAllText(Path.Combine(work, ".git", "COMMIT_EDITMSG"), "wip\n"); + File.WriteAllText(Path.Combine(work, ".git", "config"), "[core]\n"); + + Assert.False(fired.Wait(TimeSpan.FromSeconds(2)), + "only HEAD and index should wake the watcher"); + } + + [Fact] + public void Rapid_writes_are_debounced_into_one_notification() + { + // A single checkout rewrites index and HEAD and produces lock-file churn around + // both. Without debouncing that is several git spawns for one user action. + string work = MakeRepo("debounce"); + using var watcher = GitRepoWatcher.TryCreate(work); + Assert.NotNull(watcher); + + int count = 0; + watcher!.Changed += () => Interlocked.Increment(ref count); + + for (int i = 0; i < 10; i++) + { + File.WriteAllText(Path.Combine(work, ".git", "HEAD"), $"ref: refs/heads/b{i}\n"); + File.WriteAllText(Path.Combine(work, ".git", "index"), new string('x', 16 + i)); + } + + Thread.Sleep(2000); + Assert.Equal(1, Volatile.Read(ref count)); + } + + [Fact] + public void Dispose_stops_notifications() + { + string work = MakeRepo("disposed"); + var watcher = GitRepoWatcher.TryCreate(work); + Assert.NotNull(watcher); + + int count = 0; + watcher!.Changed += () => Interlocked.Increment(ref count); + watcher.Dispose(); + + File.WriteAllText(Path.Combine(work, ".git", "HEAD"), "ref: refs/heads/after\n"); + Thread.Sleep(1500); + + Assert.Equal(0, Volatile.Read(ref count)); + } +} diff --git a/tests/CodeShellManager.Tests/GitServiceThreadingTests.cs b/tests/CodeShellManager.Tests/GitServiceThreadingTests.cs new file mode 100644 index 0000000..810a8c1 --- /dev/null +++ b/tests/CodeShellManager.Tests/GitServiceThreadingTests.cs @@ -0,0 +1,125 @@ +using System; +using System.IO; +using System.Collections.Concurrent; +using System.Threading; +using System.Threading.Tasks; +using CodeShellManager.Diagnostics; +using CodeShellManager.Services; +using Xunit; + +namespace CodeShellManager.Tests; + +/// +/// Regression tests for issue #70. +/// +/// GitService used to run Process.Start — and every continuation after it — on +/// whatever thread called in. Because the poll chain begins in SessionViewModel's +/// constructor on the WPF UI thread, that put ~94 synchronous process creations per poll +/// cycle onto the UI thread at 47 sessions, freezing typing for seconds at a time. +/// +/// These tests pin the property that prevents it: GitService must never depend on, or +/// return to, the caller's SynchronizationContext. +/// +[Collection("DiagnosticTrace")] +public class GitServiceThreadingTests +{ + /// + /// A context that records every Post/Send but never runs the work. If any await in + /// GitService captures the caller's context, the continuation is handed here, never + /// executes, and the awaiting task never completes — so the test times out. + /// + private sealed class DeadSynchronizationContext : SynchronizationContext + { + public readonly ConcurrentQueue Captured = new(); + public override void Post(SendOrPostCallback d, object? state) => Captured.Enqueue("Post"); + public override void Send(SendOrPostCallback d, object? state) => Captured.Enqueue("Send"); + } + + private static async Task OnDeadContextAsync(Func> work, DeadSynchronizationContext ctx) + { + // Run on a dedicated thread that carries the dead context, mirroring the UI thread. + var tcs = new TaskCompletionSource>(); + var thread = new Thread(() => + { + SynchronizationContext.SetSynchronizationContext(ctx); + tcs.SetResult(work()); + }); + thread.IsBackground = true; + thread.Start(); + + Task started = await tcs.Task; + Task completed = await Task.WhenAny(started, Task.Delay(TimeSpan.FromSeconds(20))); + + Assert.True(ReferenceEquals(completed, started), + "GitService did not complete on a caller whose SynchronizationContext never runs " + + "work. That means an await captured the context — the exact defect that put git " + + "process creation on the WPF UI thread (issue #70)."); + + return await started; + } + + [Fact] + public async Task GetGitInfoAsync_completes_without_the_callers_context_ever_running() + { + var ctx = new DeadSynchronizationContext(); + + // The repo itself — a real git repo, so the call does real work rather than + // short-circuiting on the not-a-directory guard. + string repo = TestRepoPath(); + var (branch, _) = await OnDeadContextAsync(() => GitService.GetGitInfoAsync(repo), ctx); + + Assert.False(string.IsNullOrWhiteSpace(branch)); + } + + [Fact] + public async Task GetRepoRootAsync_completes_without_the_callers_context_ever_running() + { + var ctx = new DeadSynchronizationContext(); + + string repo = TestRepoPath(); + string? root = await OnDeadContextAsync(() => GitService.GetRepoRootAsync(repo), ctx); + + Assert.False(string.IsNullOrWhiteSpace(root)); + } + + [Fact] + public async Task Process_creation_never_happens_on_the_thread_designated_as_the_UI_thread() + { + // The tests above prove we don't *return* to the caller's context. This proves we + // don't *start* on its thread either — Process.Start sat before the first await, so + // it ran inline on the caller regardless of what any await did afterwards. + // + // Uses the GIT-SPAWN probe that shipped with the diagnosis, so the test asserts the + // same signal the live investigation read out of crash.log. + string log = Path.Combine(Path.GetTempPath(), $"csm-gitspawn-{Guid.NewGuid():N}.log"); + DiagnosticTrace.ResetForTests(log); + DiagnosticTrace.Enabled = true; + DiagnosticTrace.UiThreadId = Environment.CurrentManagedThreadId; + try + { + await GitService.GetGitInfoAsync(TestRepoPath()); + DiagnosticTrace.DrainOnce(); + + string content = File.ReadAllText(log); + Assert.Contains("GIT-SPAWN", content); + Assert.DoesNotContain("on-ui=True", content); + } + finally + { + DiagnosticTrace.Enabled = false; + DiagnosticTrace.UiThreadId = 0; + try { File.Delete(log); } catch { } + } + } + + private static string TestRepoPath() + { + // Walk up from the test binary to the repo root (the folder containing .git). + var dir = new System.IO.DirectoryInfo(AppContext.BaseDirectory); + while (dir != null && !System.IO.Directory.Exists(System.IO.Path.Combine(dir.FullName, ".git"))) + dir = dir.Parent; + + Assert.NotNull(dir); + return dir!.FullName; + } +} diff --git a/tests/CodeShellManager.Tests/SessionViewModelGitInfoTests.cs b/tests/CodeShellManager.Tests/SessionViewModelGitInfoTests.cs new file mode 100644 index 0000000..181bf56 --- /dev/null +++ b/tests/CodeShellManager.Tests/SessionViewModelGitInfoTests.cs @@ -0,0 +1,134 @@ +using System.Collections.Generic; +using CodeShellManager.Models; +using CodeShellManager.ViewModels; +using Xunit; + +namespace CodeShellManager.Tests; + +/// +/// Tests for the coalesced git notification (issue #70). +/// +/// GitBranch, GitIsDirty and GitInfoLoaded raised three separate PropertyChanged events per +/// poll per session. Each crossed a blocking Dispatcher.Invoke and rebuilt the sidebar row's +/// WPF inlines — 141 rebuilds per cycle at 47 sessions, nearly always to redraw identical +/// text. +/// +public class SessionViewModelGitInfoTests +{ + private static SessionViewModel MakeVm() => + // SessionKind.Ssh short-circuits RefreshGitInfoAsync and skips StartGitWatcher, so + // constructing one of these spawns no git processes — the tests stay hermetic. + new(new ShellSession + { + Id = "test-session", + Name = "test", + Kind = SessionKind.Ssh, + SshHost = "example.invalid" + }); + + private static List Record(SessionViewModel vm) + { + var seen = new List(); + vm.PropertyChanged += (_, e) => seen.Add(e.PropertyName ?? ""); + return seen; + } + + [Fact] + public void ApplyGitInfo_raises_exactly_one_notification() + { + var vm = MakeVm(); + var seen = Record(vm); + + vm.ApplyGitInfo("main", isDirty: true); + + Assert.Equal(new[] { nameof(SessionViewModel.GitInfoVersion) }, seen); + Assert.Equal("main", vm.GitBranch); + Assert.True(vm.GitIsDirty); + Assert.True(vm.GitInfoLoaded); + } + + [Fact] + public void An_unchanged_poll_result_raises_nothing_at_all() + { + // The important one. A branch changes maybe once an hour, so almost every poll + // returns exactly what it returned last time and must cost zero UI work. + var vm = MakeVm(); + vm.ApplyGitInfo("main", isDirty: false); + + var seen = Record(vm); + vm.ApplyGitInfo("main", isDirty: false); + vm.ApplyGitInfo("main", isDirty: false); + vm.ApplyGitInfo("main", isDirty: false); + + Assert.Empty(seen); + } + + [Fact] + public void A_changed_branch_does_notify() + { + var vm = MakeVm(); + vm.ApplyGitInfo("main", isDirty: false); + + var seen = Record(vm); + vm.ApplyGitInfo("feature/x", isDirty: false); + + Assert.Equal(new[] { nameof(SessionViewModel.GitInfoVersion) }, seen); + Assert.Equal("feature/x", vm.GitBranch); + } + + [Fact] + public void A_changed_dirty_flag_does_notify() + { + var vm = MakeVm(); + vm.ApplyGitInfo("main", isDirty: false); + + var seen = Record(vm); + vm.ApplyGitInfo("main", isDirty: true); + + Assert.Single(seen); + Assert.True(vm.GitIsDirty); + } + + [Fact] + public void First_result_notifies_even_when_the_values_are_defaults() + { + // A repo on a branch named "" is not a thing, but a *folder that is not a repo* + // returns (null, false) — and the row still has to switch from "loading" to + // "no git", so the first result must notify even though nothing "changed". + var vm = MakeVm(); + var seen = Record(vm); + + vm.ApplyGitInfo(null, isDirty: false); + + Assert.Equal(new[] { nameof(SessionViewModel.GitInfoVersion) }, seen); + Assert.True(vm.GitInfoLoaded); + } + + [Fact] + public void Setting_a_property_directly_still_notifies_once() + { + // OSC 9001 (ApplyShellIntegration) and the folder-edit reload set these individually + // rather than through ApplyGitInfo, so the single-notification contract has to hold + // on that path too. + var vm = MakeVm(); + var seen = Record(vm); + + vm.GitBranch = "from-osc"; + + Assert.Equal(new[] { nameof(SessionViewModel.GitInfoVersion) }, seen); + Assert.Equal("from-osc", vm.GitBranch); + } + + [Fact] + public void GitInfoVersion_increments_per_change() + { + var vm = MakeVm(); + int start = vm.GitInfoVersion; + + vm.ApplyGitInfo("a", isDirty: false); + vm.ApplyGitInfo("b", isDirty: false); + vm.ApplyGitInfo("b", isDirty: false); // no-op + + Assert.Equal(start + 2, vm.GitInfoVersion); + } +} diff --git a/tests/CodeShellManager.Tests/SessionViewModelGitPollingTests.cs b/tests/CodeShellManager.Tests/SessionViewModelGitPollingTests.cs index 280ee9f..3384245 100644 --- a/tests/CodeShellManager.Tests/SessionViewModelGitPollingTests.cs +++ b/tests/CodeShellManager.Tests/SessionViewModelGitPollingTests.cs @@ -9,13 +9,35 @@ public class SessionViewModelGitPollingTests { [Fact] public void GitPollInterval_LocalIsTenSeconds() => - Assert.Equal(TimeSpan.FromSeconds(10), SessionViewModel.GitPollIntervalFor(SessionKind.Local)); + Assert.Equal(TimeSpan.FromSeconds(10), SessionViewModel.GitPollIntervalFor(SessionKind.Local, isForeground: true)); [Fact] public void GitPollInterval_WslIsSlower() { // Each WSL probe is a wsl.exe spawn (LxssManager hop) and keeps the VM awake; // three times the local cadence is the documented trade. - Assert.Equal(TimeSpan.FromSeconds(30), SessionViewModel.GitPollIntervalFor(SessionKind.Wsl)); + Assert.Equal(TimeSpan.FromSeconds(30), SessionViewModel.GitPollIntervalFor(SessionKind.Wsl, isForeground: true)); + } + + // A poll is ~all process creation, so 46 background sessions polling every 10s was pure + // overhead to learn nothing had changed. Real git operations arrive via GitRepoWatcher; + // this slow poll only catches working-tree edits (issue #70). + [Theory] + [InlineData(SessionKind.Local)] + [InlineData(SessionKind.Wsl)] + public void GitPollInterval_BackgroundBacksOffHard(SessionKind kind) => + Assert.Equal(TimeSpan.FromSeconds(120), + SessionViewModel.GitPollIntervalFor(kind, isForeground: false)); + + [Fact] + public void GitPollInterval_BackgroundIsAlwaysSlowerThanForeground() + { + foreach (var kind in new[] { SessionKind.Local, SessionKind.Wsl, SessionKind.Ssh }) + { + Assert.True( + SessionViewModel.GitPollIntervalFor(kind, isForeground: false) > + SessionViewModel.GitPollIntervalFor(kind, isForeground: true), + $"{kind}: a pane you cannot see must never poll more often than the one you can"); + } } }