From d6294e714ff0ec1ce42f72d453ea5982806a7692 Mon Sep 17 00:00:00 2001 From: Allan Thraen Date: Tue, 8 Sep 2026 11:31:47 +0200 Subject: [PATCH 1/2] perf(git): take the git pipeline off the UI thread, and stop polling blind MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Fixes the typing stall in issue #70: input stops echoing, then arrives all at once. Diagnosed by measurement rather than inspection, after three of the four standing hypotheses turned out to be wrong. ## What the trace said Instrumented, then run at the reporter's real workload (47 sessions): 42 UI-STALL events, worst 28547ms d974929c OUTPUT flush len=3350 dispatcher-latency=12781ms prio=fg since-input=22312ms That flush line is the bug report restated as data: a foreground pane blocked 12.8s, accumulating 3.3KB, then rendering it in one blob. Ruled out, each with evidence: - renderer starvation 0 write-blocked, 3 paint-lag in 4 minutes - ConPTY write backpressure 662 PTY-WROTE, 661 of them 0ms - stale IsForeground the typed pane logged prio=fg throughout - output flooding the queue 69KB across 12 sessions in a 68s window that still contained a 9.1s stall The last one is what broke it open: it falsified the theory this issue is titled after, and pointed at work on the UI thread that wasn't terminal I/O. ## Root cause An async method runs everything before its first await synchronously on the calling thread. RunGitFullAsync had Process.Start there, and the poll chain starts in SessionViewModel's constructor, which LaunchSessionAsync runs on the UI thread — so the SynchronizationContext was captured, every continuation came back, and git process creation happened on the UI thread. ~94 spawns per 10s cycle at 47 sessions. Measured here: Process.Start alone is ~15ms, so ~1.4s of hard UI block per cycle on an idle machine, before contention. And the cost is process creation, not git — `git --version` is 42ms against `branch --show-current` at 41ms — so there was never a faster query to switch to. #70's step 4 had the right target and the wrong mechanism: it called this "background load". It was never background. ## The three fixes 1. GitService cannot depend on the caller's thread. RunGitFullAsync is Task.Run-wrapped so Process.Start can't run inline; every await is ConfigureAwait(false) so nothing climbs back. Both halves are needed — ConfigureAwait alone would not have moved Process.Start. SessionViewModel also starts the poll loop under Task.Run so the context is never captured. 2. GitRepoWatcher replaces most of the polling. A debounced FileSystemWatcher on .git/HEAD and .git/index catches checkout, commit, merge and staging immediately. It follows the `gitdir:` indirection, so a linked worktree watches its own HEAD rather than the main repo's and reports the right branch. Polling survives only for working-tree edits, which dirty status without touching .git: foreground 10s, background 120s, plus an immediate refresh when a pane becomes active. 3. One notification instead of three. GitBranch/GitIsDirty/GitInfoLoaded are hand-written properties sharing GitInfoVersion; as [ObservableProperty] they raised three events per poll per session, each crossing a blocking Dispatcher.Invoke and rebuilding a sidebar row's WPF inlines — 141 rebuilds per cycle. ApplyGitInfo also returns early on an unchanged result, which is almost every poll. ## Instrumentation, which had rotted The trace could not answer the question it existed for. dispatcher-latency was added in 092b801 and deleted by 71e1294 — the coalescing commit for this same issue — which dropped the enqueue timestamp along with the per-chunk post. The fix removed the instrument that measured the problem, invisibly, because the trace still produced plausible output. It would also have caused the stall it measured: Trace() did CreateDirectory + a synchronous AppendAllText per call, on the PTY thread and the UI thread. - DiagnosticTrace: bounded queue, one background drain, timestamps taken at call time. Overflow reported in-band, since a silent gap in a latency log reads as a stall that never happened. - dispatcher-latency restored on the coalesced flush, with the priority the batch was queued at and time-since-last-input. - UiThreadHeartbeat: UI lateness attributed to no session, the only way to separate real saturation from Background priority yielding correctly. - Page-side term.write duration and paint lag, threshold-gated. The host is blind past PostWebMessageAsString and renderer starvation was still live. - GIT-SPAWN on-ui= spawn=, which is what proved the diagnosis. ## Tests 19 new, 367 total, 0 warnings. GitServiceThreadingTests 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 fail against the pre-fix GitService (verified by reverting it) and pass after. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01NDsEfog5kVkT5NmX1Ya5be --- src/CodeShellManager/Assets/terminal-init.js | 40 ++++- .../Diagnostics/DiagnosticTrace.cs | 137 +++++++++++++++ .../Diagnostics/UiThreadHeartbeat.cs | 80 +++++++++ src/CodeShellManager/MainWindow.xaml.cs | 31 +++- .../Services/GitRepoWatcher.cs | 135 +++++++++++++++ src/CodeShellManager/Services/GitService.cs | 51 ++++-- .../Terminal/TerminalBridge.cs | 106 ++++++++++-- .../ViewModels/SessionViewModel.cs | 141 +++++++++++++-- .../DiagnosticTraceCollection.cs | 10 ++ .../DiagnosticTraceTests.cs | 88 ++++++++++ .../GitRepoWatcherTests.cs | 161 ++++++++++++++++++ .../GitServiceThreadingTests.cs | 125 ++++++++++++++ .../SessionViewModelGitInfoTests.cs | 134 +++++++++++++++ 13 files changed, 1199 insertions(+), 40 deletions(-) create mode 100644 src/CodeShellManager/Diagnostics/DiagnosticTrace.cs create mode 100644 src/CodeShellManager/Diagnostics/UiThreadHeartbeat.cs create mode 100644 src/CodeShellManager/Services/GitRepoWatcher.cs create mode 100644 tests/CodeShellManager.Tests/DiagnosticTraceCollection.cs create mode 100644 tests/CodeShellManager.Tests/DiagnosticTraceTests.cs create mode 100644 tests/CodeShellManager.Tests/GitRepoWatcherTests.cs create mode 100644 tests/CodeShellManager.Tests/GitServiceThreadingTests.cs create mode 100644 tests/CodeShellManager.Tests/SessionViewModelGitInfoTests.cs 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 3d2300e..195c614 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(); @@ -1781,9 +1792,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; @@ -1914,7 +1926,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) { @@ -5247,6 +5264,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 9d50ff4..1a3c74b 100644 --- a/src/CodeShellManager/Services/GitService.cs +++ b/src/CodeShellManager/Services/GitService.cs @@ -14,11 +14,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); @@ -43,7 +43,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(); @@ -80,7 +80,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: @@ -123,7 +123,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; @@ -149,7 +149,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) @@ -159,11 +159,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) { var psi = new ProcessStartInfo("git") @@ -175,19 +183,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 6bc2bc0..4e82a2d 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. @@ -84,23 +104,107 @@ public SessionViewModel(ShellSession session) { Session = session; Runner = new SessionRunner(session); - _ = RefreshGitInfoAsync(); - _ = PollGitInfoAsync(_gitPollCts.Token); + + // Task.Run so the WPF SynchronizationContext is NOT captured. This constructor runs + // on the UI thread (MainWindow.LaunchSessionAsync), and without this every await in + // the git chain resumed there — including the synchronous Process.Start ahead of the + // first await. That put ~94 process creations per poll cycle on the UI thread at 47 + // sessions. GitService is hardened independently; this is the other half (issue #70). + _ = Task.Run(() => RefreshGitInfoAsync()); + _ = Task.Run(() => PollGitInfoAsync(_gitPollCts.Token)); + StartGitWatcher(); } public async Task RefreshGitInfoAsync() { if (Session.IsRemote || _gitOverriddenByOsc) return; - var (branch, isDirty) = await GitService.GetGitInfoAsync(Session.WorkingFolder); - GitBranch = branch; - GitIsDirty = isDirty; - GitInfoLoaded = true; + var (branch, isDirty) = await GitService.GetGitInfoAsync(Session.WorkingFolder) + .ConfigureAwait(false); + 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 // that should participate in sibling detection, shared accent color, and clusters. if (RepoRoot == null) - RepoRoot = await GitService.GetRepoRootAsync(Session.WorkingFolder); + RepoRoot = await GitService.GetRepoRootAsync(Session.WorkingFolder) + .ConfigureAwait(false); + } + + /// + /// 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 void StartGitWatcher() + { + if (Session.IsRemote) return; // no local .git to watch + _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; + _ = Task.Run(() => RefreshGitInfoAsync()); } /// Short repo + branch label shown beneath the session name when sibling worktrees are open. @@ -117,11 +221,16 @@ public string WorktreeSubtitle private async Task PollGitInfoAsync(CancellationToken ct) { - using var timer = new PeriodicTimer(TimeSpan.FromSeconds(10)); try { - while (await timer.WaitForNextTickAsync(ct)) - await RefreshGitInfoAsync(); + while (!ct.IsCancellationRequested) + { + // Interval is read each iteration, so promoting a session to the foreground + // speeds up its next poll without having to restart the loop. + int delay = IsForegroundSession ? ForegroundPollMs : BackgroundPollMs; + await Task.Delay(delay, ct).ConfigureAwait(false); + await RefreshGitInfoAsync().ConfigureAwait(false); + } } catch (OperationCanceledException) { } } @@ -247,6 +356,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..03e4447 --- /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() => + // IsRemote short-circuits RefreshGitInfoAsync, so constructing one of these spawns + // no git processes and starts no watcher — the test stays hermetic. + new(new ShellSession + { + Id = "test-session", + Name = "test", + IsRemote = true, + 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); + } +} From 8e474002e1df5c305d07f3d5a8d138284e5406ca Mon Sep 17 00:00:00 2001 From: Allan Thraen Date: Tue, 8 Sep 2026 11:32:47 +0200 Subject: [PATCH 2/2] docs: record the UI-thread rule, plus the chocolatey moderation block MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two unrelated additions; the second is a drive-by from earlier in the same session and can be dropped from this PR if it belongs elsewhere. **Never spawn a process on the UI thread.** The mechanism behind #70, with the measurements that make the case: ~85-90% of any git call is process startup (`git --version` 42ms vs `branch --show-current` 41ms), so there is no faster query — the only fixes are to be off the UI thread and to not spawn at all. Records the three load-bearing rules and points at the regression tests, since `ConfigureAwait(false)` and a `Task.Run` wrapper both look exactly like the kind of thing a later reader tidies away. **Chocolatey is blocked on moderation.** The post-tag checklist said to dispatch both mirrors unconditionally; v0.5.0 is still in the human review queue, so dispatching for a newer tag fails rather than queueing behind it. Also records that the GitHub MSI download counter is the union of all three channels — the winget manifest's InstallerUrl and chocolateyinstall.ps1's substituted __URL64__ both point at that same asset — so the three numbers must not be summed. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01NDsEfog5kVkT5NmX1Ya5be --- CLAUDE.md | 96 ++++++++++++++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 92 insertions(+), 4 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 33c2e95..cd1651a 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/` | @@ -134,6 +135,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: @@ -491,14 +544,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`.