perf: stop the profiler and duplicate git reads from causing the lag (#248)

Investigating reported latency when switching between worktrees on a
live production instance. Two independent causes, both measured from
that instance's `perf.log`.

## 1. The profiler was a top source of the lag it measured

`perfLog` called `appendFileSync` once per line, on the main thread —
the same thread serving IPC. At production event rates that's roughly
**1M blocking writes per session**.

It compounded: `perf.log` is deliberately append-only across sessions,
but had no rotation and had reached **182MB / 1.1M lines**, so every
write was appending to an ever-growing file.

And two categories were logged *unconditionally* while every other
category had a threshold, on the assumption they were infrequent. They
aren't — they fire on every panel refresh for every worktree. One
session produced:

| category | lines in one session |
|---|---|
| `git-op` | 114,840 |
| `changed-files` | 77,512 |

Fixes:
- Buffered writes, flushed async on a 1s / 500-line trigger via
`appendFile`. `flushPerfLogSync()` drains on shutdown so the tail of a
session isn't lost.
- Rotation at 10MB into `perf.log.1`, matching `debug.log`. `log:perf`
now uses `tail -F` to survive rotation; `log:perf:clear` removes both
files.
- Both categories gated at 50ms like everything else.

## 2. The branch-mode git read was running twice

Two independent cache keys — `'changedFiles'` and `'branchChangedFiles'`
— fetch byte-identical `mode=branch` data for the same worktree with no
coordination. Each `getChangedFiles` costs three git subprocess spawns.

The log shows the duplication directly, across 77k samples and 179
distinct worktree paths:

| mode | requests | ratio |
|---|---|---|
| `branch` | 51,343 | **1.96 : 1** |
| `working` | 26,212 | |

Working-tree and branch reads are requested by the same surfaces, so
absent duplication these should be near 1:1. Nearly 2:1 only makes sense
if the branch fetch runs twice.

New `requestChangedFiles` joins calls already overlapping in time, keyed
by `(mode, path)`. Dedup is **in-flight only** — nothing is retained
past settlement — so it cannot serve stale data. `force` opts out of the
join entirely for invalidation-driven refreshes, which must not be
answered by a request that started before the change landed.

## Ruled out

Worth recording so the next person doesn't re-investigate: renderer
rendering (zero `[render-slow]` entries), shell-wrapped git spawns (uses
`execFile` directly), `useBackend()` identity churn (stable module
singleton), the reducer reference-identity anti-pattern (already uses
`findIndex + slice`), and event cascades (only 4 `[cascade]` lines).

I also initially blamed `jsonClaude/*` streaming for main-thread blocks
and **retracted it** — `[snapshot]` lines during lag show `store=1/s
ipc=1/s` with near-empty `topEventTypes`. That was inferring causation
from adjacency in the log. No changes were made to that slice.

## Relationship to #247

Complementary, different layers — #247 is main-side git caching and
index-lock contention; this is renderer-side request dedup and perf-log
cost. I deliberately stayed out of `git-poll-cache.ts` /
`git-ops-state.ts`.

I verified the one real interaction risk — that a `force` refresh here
could be served a stale value by #247's main-side cache — and **it's
safe**: #247 sets `fingerprintable: mode === 'branch'`, so working-tree
reads are never fingerprint-skipped, and the branch fingerprint spans
every input a `base...HEAD` diff depends on. The only cached answer to a
force refresh is the deliberate busy-skip during a real rebase, bounded
at 10 consecutive skips.

**Whoever merges second gets one conflict**, at the `getChangedFiles`
perf-log call site in `src/main/worktree.ts`. Resolution is to combine,
not to take a side: keep #247's `value`/`cached` and wrap it in this
PR's `if (ms >= SLOW_CHANGED_FILES_MS)`.

One decision for merge time: #247's log line ends with `${cached ? '
cached' : ''}`, but a cache hit returns in ~0ms and so never clears the
50ms gate. Merging both as-is silently destroys the "is the cache
working?" signal that flag exists to provide. Either exempt cache hits
from the threshold or count them separately — worth choosing
deliberately.

## Test plan

- [x] `npm run typecheck` clean
- [x] `npx electron-vite build` clean
- [x] `npx vitest run` — 1028 passed, 1 skipped
- [ ] CI green

⚠️ **Local test runs are unreliable on the machine this was developed
on.** Three git-spawning integration tests
(`worktree-watcher.integration.test.ts`, `git-ops-state.test.ts`,
`path-fix.test.ts`, plus `git-poll-cache.test.ts`) fail intermittently
on their 5s timeout under full-suite load, and pass 3/3 in isolation.
Confirmed load-sensitive rather than caused by this branch by
interleaving dirty/clean full-suite runs — clean `main` fails the same
test and this branch passes on green runs. Flagging as a likely
pre-existing CI flake worth a follow-up issue; not touched here.

🤖 Generated with [Claude Code](https://claude.com/claude-code)

---------

Co-authored-by: Claude Opus 4.7 <noreply@anthropic.com>

Author: frenchie4111

CLAUDE.md

@@ -306,8 +306,19 @@ Two log files in `userData`:
   (removes both `debug.log` and `debug.log.1`).
 - **`perf.log`** — perf trace. **Append-only across sessions** so lag
   that happened earlier (possibly before the most recent restart) is
-  still inspectable. Tail with `npm run log:perf`. Clear before a fresh
-  repro with `npm run log:perf:clear`.
+  still inspectable. Rotated at 10MB into `perf.log.1` (one archive
+  only). Tail with `npm run log:perf` (uses `tail -F` so it survives
+  rotation). Clear before a fresh repro with `npm run log:perf:clear`
+  (removes both `perf.log` and `perf.log.1`).
+
+  Writes are **buffered and async** — lines accumulate and flush on a
+  1 s timer or at 500 buffered lines, whichever comes first, via
+  `appendFile` rather than `appendFileSync`. This matters: the profiler
+  runs on the same main thread it's measuring, so a blocking write per
+  line makes it a source of the lag it reports. `flushPerfLogSync()`
+  drains the buffer on shutdown so the tail of a session isn't lost.
+  The corollary for anyone reading the log live: the last second or so
+  of events may not be on disk yet.
 
 What gets written to `perf.log` (and where the threshold lives):
 
@@ -327,11 +338,20 @@ What gets written to `perf.log` (and where the threshold lives):
   at 60 fps; `src/renderer/main.tsx`). Forwarded from the renderer over
   the `perf:logSlowRender` fire-and-forget signal — telemetry must not
   block the render.
-- `[changed-files]` — every `getChangedFiles` / `getCommitChangedFiles`
-  call (these are infrequent and a complete trace is invaluable).
-- `[git-op]` — per-call timing breakdown for slow git functions, capturing exec/post/bytes split.
+- `[changed-files]` — `getChangedFiles` / `getCommitChangedFiles` /
+  `getCommitRangeChangedFiles` calls taking ≥ `SLOW_CHANGED_FILES_MS`
+  (50 ms; `src/main/worktree.ts`).
+- `[git-op]` — per-call timing breakdown (exec/post/bytes split) for git
+  functions taking ≥ `SLOW_GIT_OP_MS` (50 ms; `src/main/worktree.ts`).
 - `[microtask-drift]` — main-thread blocks ≥50ms (higher resolution than the 500ms event-loop sampler).
 
+`[changed-files]` and `[git-op]` were originally logged unconditionally,
+on the theory that they were infrequent enough for a complete trace to
+be worth it. They aren't — they fire on every panel refresh for every
+worktree, and a single session produced 77k and 115k lines respectively.
+Don't un-gate them for a "complete" trace; if you need one for a
+specific repro, lower the constant temporarily instead.
+
 The HUD at **Cmd+Opt+P** shows live aggregates (rates, history sparkline,
 React commits per second, top event types). `perf.log` captures the
 per-event detail the HUD can't display. They're complementary —

package.json

@@ -13,8 +13,8 @@
     "dev:debug": "sh -c 'trap \"kill 0\" EXIT; tail -F \"$HOME/Library/Application Support/Harness (Dev)/debug.log\" & ELECTRON_DISABLE_SANDBOX=1 electron-vite dev'",
     "log": "tail -F ~/Library/Application\\ Support/harness/debug.log",
     "log:clear": "rm -f ~/Library/Application\\ Support/harness/debug.log ~/Library/Application\\ Support/harness/debug.log.1",
-    "log:perf": "tail -f ~/Library/Application\\ Support/harness/perf.log",
-    "log:perf:clear": "rm -f ~/Library/Application\\ Support/harness/perf.log",
+    "log:perf": "tail -F ~/Library/Application\\ Support/harness/perf.log",
+    "log:perf:clear": "rm -f ~/Library/Application\\ Support/harness/perf.log ~/Library/Application\\ Support/harness/perf.log.1",
     "build": "electron-vite build && vite build --config vite.web.config.ts",
     "build:web": "vite build --config vite.web.config.ts",
     "build:headless": "vite build --config vite.headless.config.ts && vite build --config vite.headless-web.config.ts",

src/main/index.ts

@@ -121,7 +121,7 @@ import { getControlServerInfo } from './control-server'
 import { recordActivity, getActivityLog, clearAllActivity, clearActivityForWorktree, sealAllActive, touchActivityMeta, finalizeActivity, type ActivityState, type PRState } from './activity'
 import { log, getLogFilePath } from './debug'
 import { loadCustomThemes } from './themes-loader'
-import { perfLog } from './perf-log'
+import { perfLog, flushPerfLogSync } from './perf-log'
 import { buildInitialAppState } from './build-initial-state'
 import { AnnouncementsPoller } from './announcements-poller'
 
@@ -4777,6 +4777,7 @@ if (desktopShellMod && desktopEarly) {
       // running (intentional; see plans/remote-main.md §4).
       sshTunnelManager.closeAll()
       worktreeWatcher.shutdown()
+      flushPerfLogSync()
     },
     setWarnBeforeQuitting
   })
@@ -4802,6 +4803,7 @@ if (desktopShellMod && desktopEarly) {
     sshTunnelManager.closeAll()
     sealAllActive()
     saveConfigSync(config)
+    flushPerfLogSync()
     process.exit(0)
   }
   process.on('SIGINT', shutdown)

src/main/perf-log.ts

@@ -1,12 +1,25 @@
-import { appendFileSync, existsSync } from 'fs'
+import { appendFile, appendFileSync, existsSync, renameSync, statSync, unlinkSync } from 'fs'
 import { join } from 'path'
 import { userDataDir } from './paths'
 
 // Append-only across sessions — the user is debugging lag that may have
 // happened earlier in the session, possibly before the most recent restart,
-// so unlike debug.log we don't truncate on startup.
+// so unlike debug.log we don't truncate on startup. We do rotate, because an
+// unbounded file is both a disk hazard and a write-latency one.
+//
+// Writes are buffered and flushed asynchronously. The naive version called
+// appendFileSync per line, which put a blocking syscall on the main thread for
+// every traced event — at production event rates that's ~1M blocking writes a
+// session, i.e. the profiler became a top source of the lag it was measuring.
+const FLUSH_INTERVAL_MS = 1000
+const MAX_BUFFERED_LINES = 500
+const MAX_LOG_BYTES = 10 * 1024 * 1024
+
 let logPath: string | null = null
 let headerWritten = false
+let buffer: string[] = []
+let flushTimer: NodeJS.Timeout | null = null
+let flushing = false
 
 function getLogPath(): string {
   if (!logPath) {
@@ -15,15 +28,49 @@ function getLogPath(): string {
   return logPath
 }
 
+/** Rotate into a single `.1` archive once the live file exceeds the cap,
+ *  mirroring debug.log. Sync is fine here: it happens at most once per 10MB. */
+function rotateIfNeeded(path: string): void {
+  try {
+    if (statSync(path).size < MAX_LOG_BYTES) return
+    const archive = `${path}.1`
+    if (existsSync(archive)) unlinkSync(archive)
+    renameSync(path, archive)
+  } catch {
+    // Missing file or a losing race with another rotation — nothing to do.
+  }
+}
+
+function flush(): void {
+  if (flushing || buffer.length === 0) return
+  flushing = true
+  const chunk = buffer.join('')
+  buffer = []
+  const path = getLogPath()
+  rotateIfNeeded(path)
+  appendFile(path, chunk, () => {
+    flushing = false
+    // Anything queued while the write was in flight goes out on the next tick
+    // rather than recursing here, so a hot stream can't starve the loop.
+    if (buffer.length > 0) scheduleFlush()
+  })
+}
+
+function scheduleFlush(): void {
+  if (flushTimer) return
+  flushTimer = setTimeout(() => {
+    flushTimer = null
+    flush()
+  }, FLUSH_INTERVAL_MS)
+  // Never hold the process open just to write a diagnostic log.
+  flushTimer.unref?.()
+}
+
 function ensureHeader(path: string): void {
   if (headerWritten) return
   headerWritten = true
   const sep = existsSync(path) ? '\n' : ''
-  try {
-    appendFileSync(path, `${sep}=== session started at ${new Date().toISOString()} ===\n`)
-  } catch {
-    // ignore write errors
-  }
+  buffer.push(`${sep}=== session started at ${new Date().toISOString()} ===\n`)
 }
 
 export function perfLog(category: string, message: string, data?: unknown): void {
@@ -38,8 +85,19 @@ export function perfLog(category: string, message: string, data?: unknown): void
       line += ' [unserializable]'
     }
   }
+  buffer.push(line + '\n')
+  // Bound memory if something floods faster than the flush interval.
+  if (buffer.length >= MAX_BUFFERED_LINES) flush()
+  else scheduleFlush()
+}
+
+/** Drain synchronously — for shutdown, where an async flush would be dropped. */
+export function flushPerfLogSync(): void {
+  if (buffer.length === 0) return
+  const chunk = buffer.join('')
+  buffer = []
   try {
-    appendFileSync(path, line + '\n')
+    appendFileSync(getLogPath(), chunk)
   } catch {
     // ignore write errors
   }

src/main/worktree.ts

@@ -563,6 +563,13 @@ async function numstatExec(
   }
 }
 
+// These fire on every panel refresh for every worktree — thousands per minute
+// in a busy session. Tracing all of them made the log (and its writes) a
+// bigger cost than the thing being traced, so both are gated the same way
+// every other perf category is: only the slow ones are worth a line.
+const SLOW_GIT_OP_MS = 50
+const SLOW_CHANGED_FILES_MS = 50
+
 function logGitOp(
   name: string,
   ctx: Record<string, unknown>,
@@ -574,6 +581,7 @@ function logGitOp(
 ): void {
   const total = performance.now() - t0
   const postMs = Math.max(0, total - walledExec)
+  if (cumExec < SLOW_GIT_OP_MS && total < SLOW_GIT_OP_MS) return
   perfLog(
     'git-op',
     `${name} exec=${cumExec.toFixed(0)}ms post=${postMs.toFixed(0)}ms bytes=${outputBytes}`,
@@ -609,11 +617,13 @@ export async function getChangedFiles(
   const t0 = performance.now()
   const result = await getChangedFilesImpl(worktreePath, mode)
   const ms = performance.now() - t0
-  perfLog(
-    'changed-files',
-    `mode=${mode} path=${basename(worktreePath)} took=${ms.toFixed(0)}ms files=${result.length}`,
-    { worktreePath, mode, ms: +ms.toFixed(1), fileCount: result.length }
-  )
+  if (ms >= SLOW_CHANGED_FILES_MS) {
+    perfLog(
+      'changed-files',
+      `mode=${mode} path=${basename(worktreePath)} took=${ms.toFixed(0)}ms files=${result.length}`,
+      { worktreePath, mode, ms: +ms.toFixed(1), fileCount: result.length }
+    )
+  }
   return result
 }
 
@@ -795,11 +805,13 @@ export async function getCommitChangedFiles(
   const t0 = performance.now()
   const result = await getCommitChangedFilesImpl(worktreePath, hash)
   const ms = performance.now() - t0
-  perfLog(
-    'changed-files',
-    `mode=commit path=${basename(worktreePath)} took=${ms.toFixed(0)}ms files=${result.length}`,
-    { worktreePath, mode: 'commit', hash, ms: +ms.toFixed(1), fileCount: result.length }
-  )
+  if (ms >= SLOW_CHANGED_FILES_MS) {
+    perfLog(
+      'changed-files',
+      `mode=commit path=${basename(worktreePath)} took=${ms.toFixed(0)}ms files=${result.length}`,
+      { worktreePath, mode: 'commit', hash, ms: +ms.toFixed(1), fileCount: result.length }
+    )
+  }
   return result
 }
 
@@ -893,11 +905,14 @@ export async function getCommitRangeChangedFiles(
   }
 
   logGitOp('getCommitRangeChangedFiles', { fromHash, toHash }, t0, walledExec, cumExec, outputBytes, execParts)
-  perfLog(
-    'changed-files',
-    `mode=range path=${basename(worktreePath)} took=${(performance.now() - t0).toFixed(0)}ms files=${result.length}`,
-    { worktreePath, mode: 'range', fromHash, toHash, ms: +(performance.now() - t0).toFixed(1), fileCount: result.length }
-  )
+  const rangeMs = performance.now() - t0
+  if (rangeMs >= SLOW_CHANGED_FILES_MS) {
+    perfLog(
+      'changed-files',
+      `mode=range path=${basename(worktreePath)} took=${rangeMs.toFixed(0)}ms files=${result.length}`,
+      { worktreePath, mode: 'range', fromHash, toHash, ms: +rangeMs.toFixed(1), fileCount: result.length }
+    )
+  }
   return result
 }
 

src/renderer/components/ChangedFilesPanel.tsx

@@ -4,6 +4,7 @@ import type { ChangedFile } from '../types'
 import { Tooltip } from './Tooltip'
 import { RightPanel } from './RightPanel'
 import { useWatchedQuery } from '../hooks/useWatchedQuery'
+import { requestChangedFiles } from '../hooks/changed-files-request'
 import { useBackend } from '../backend'
 
 type Mode = 'working' | 'branch'
@@ -38,10 +39,10 @@ interface ChangedFilesData {
 
 export function ChangedFilesPanel({ worktreePath, onOpenDiff, onSendToAgent, onOpenReview }: ChangedFilesPanelProps): JSX.Element {
   const backend = useBackend()
-  const fetcher = useCallback(async (path: string): Promise<ChangedFilesData> => {
+  const fetcher = useCallback(async (path: string, opts: { force: boolean }): Promise<ChangedFilesData> => {
     const [working, branch] = await Promise.all([
-      backend.getChangedFiles(path, 'working'),
-      backend.getChangedFiles(path, 'branch'),
+      requestChangedFiles(backend, path, 'working', opts),
+      requestChangedFiles(backend, path, 'branch', opts),
     ])
     return { working, branch }
   }, [backend])

src/renderer/components/CollapsedRightPanel.tsx

@@ -21,6 +21,7 @@ import { CommitInfoModal } from './CommitInfoModal'
 import { useActiveBackend, usePanes, usePrs, useRepoConfigs, useSettings, useWorktrees } from '../store'
 import { useBackend } from '../backend'
 import { useWatchedQuery } from '../hooks/useWatchedQuery'
+import { requestChangedFiles } from '../hooks/changed-files-request'
 import { useReviewProgress } from '../review-progress'
 import { getLeaves } from '../../shared/state/terminals'
 import { effectiveHiddenRightPanels } from '../../shared/state/repo-configs'
@@ -86,10 +87,10 @@ export function CollapsedRightPanel({
   // and BranchCommitsPanel so the expanded right column doesn't re-fetch
   // when the user toggles between collapsed and expanded.
   const changedFilesFetcher = useCallback(
-    async (path: string): Promise<ChangedFilesData> => {
+    async (path: string, opts: { force: boolean }): Promise<ChangedFilesData> => {
       const [working, branch] = await Promise.all([
-        backend.getChangedFiles(path, 'working'),
-        backend.getChangedFiles(path, 'branch')
+        requestChangedFiles(backend, path, 'working', opts),
+        requestChangedFiles(backend, path, 'branch', opts)
       ])
       return { working, branch }
     },

src/renderer/hooks/changed-files-request.ts

@@ -0,0 +1,41 @@
+import type { ChangedFile } from '../types'
+import type { ElectronAPI } from '../types'
+
+// In-flight dedup for `getChangedFiles`.
+//
+// The panels that show changed files don't share a cache entry: ChangedFilesPanel
+// keys on 'changedFiles' (and fetches working+branch together) while
+// useChangedFilesSet keys on 'branchChangedFiles'. When both are mounted they
+// ask the main process the same `mode: 'branch'` question at the same instant,
+// and each answer costs three git subprocesses. Production perf traces showed a
+// steady 2:1 branch:working ratio — i.e. one of every two branch diffs was
+// redundant.
+//
+// Dedup is deliberately in-flight only; nothing is cached past settlement, so a
+// join can only ever merge calls that already overlap in time. `force` skips the
+// join for invalidation-driven refreshes, which must not be served by a request
+// that started before the change they're reacting to.
+
+type Mode = 'working' | 'branch'
+
+const inFlight = new Map<string, Promise<ChangedFile[]>>()
+
+export function requestChangedFiles(
+  backend: ElectronAPI,
+  path: string,
+  mode: Mode,
+  opts: { force?: boolean } = {}
+): Promise<ChangedFile[]> {
+  const key = `${mode}::${path}`
+  if (!opts.force) {
+    const existing = inFlight.get(key)
+    if (existing) return existing
+  }
+  const promise = backend.getChangedFiles(path, mode).finally(() => {
+    // Only clear if we're still the current entry — a forced refresh may have
+    // replaced us while this request was in flight.
+    if (inFlight.get(key) === promise) inFlight.delete(key)
+  })
+  inFlight.set(key, promise)
+  return promise
+}

src/renderer/hooks/useChangedFilesSet.ts

@@ -2,6 +2,7 @@ import { useCallback, useMemo } from 'react'
 import type { ChangedFile } from '../types'
 import { useBackend } from '../backend'
 import { useWatchedQuery } from './useWatchedQuery'
+import { requestChangedFiles } from './changed-files-request'
 
 /** Single-letter glyphs that mirror the labels used in the
  *  ChangedFilesPanel "Committed" section. Surfaces that want to
@@ -45,7 +46,8 @@ const EMPTY: ChangedFilesSetResult = {
 export function useChangedFilesSet(worktreePath: string | null): ChangedFilesSetResult {
   const backend = useBackend()
   const fetcher = useCallback(
-    (path: string) => backend.getChangedFiles(path, 'branch'),
+    (path: string, opts: { force: boolean }) =>
+      requestChangedFiles(backend, path, 'branch', opts),
     [backend]
   )