perf(feed-debug): pace persistence appends by time instead of per runtimes replacement

docs/superpowers/plans/2026-09-03-feed-debug-persist-batching.md

@@ -0,0 +1,71 @@
+# Feed debug: batch persistence appends by time
+
+Fixes #748. Refs #722, #103.
+
+## Problem
+
+`useFeedDebugPersist` runs in a `useEffect` keyed on the `runtimes` map,
+which is replaced dozens of times per second while a turn streams. Every
+replacement that finds new feed-debug entries sends them to main at once,
+and the success path re-drains immediately, so the append cadence follows
+the streaming cadence: 8,649–10,159 `debug:append-feed-log` invokes in a
+77-minute run (20/s in bursts), each one a `writeFile(flag:'a')` plus a
+retention-prune schedule on the main thread, with p95 352 ms and a 1.2 s
+worst case on the Sep 1 run.
+
+## Design
+
+The hook keeps its two cursors (persisted / in-flight) and the one-append-
+in-flight rule — those carry the retry and durability semantics — and only
+changes WHEN a flush is started:
+
+- A pure policy, `decideFeedDebugFlush`, answers "flush now", "arm a timer
+  for N ms" or "nothing" from `{ pendingCount, pendingBytes, lastAttemptAt,
+  now, inFlight }`. The first batch after a quiet period flushes
+  immediately, so the entry that explains a bad paint is on disk within one
+  IPC round trip. Anything that arrives within `FEED_DEBUG_FLUSH_INTERVAL_MS`
+  (1.5 s) of the last attempt waits for one per-session timer.
+  `FEED_DEBUG_FLUSH_MAX_PENDING` (256 entries) or
+  `FEED_DEBUG_FLUSH_MAX_PENDING_BYTES` (1 MiB, from the ring's cached per-
+  entry estimate) forces an immediate flush: the ring is byte-capped at
+  4 MiB and evicts from the head, and with the #722 shape (hundreds of KB
+  per entry) twenty entries already exceed it, so a count ceiling alone
+  would let unpersisted entries be evicted while waiting.
+- On IPC success or failure the hook re-runs the policy, which arms the
+  timer unless a ceiling is crossed; a failed attempt counts as an attempt
+  so a rejecting main does not turn streaming into a retry storm.
+- A session that leaves `runtimes` (replacement, pane close, tab kill,
+  reload) gets one final, unpaced flush of its trailing entries from the
+  last runtime snapshot — parked until an in-flight append resolves if
+  there is one — then its bookkeeping is dropped. Those entries (exit code,
+  kill reason) are the ones debug bundles read for closed panes.
+- Timers live in a ref keyed by session and are cleared on unmount only —
+  the effect itself re-runs on every runtimes replacement and must not tear
+  them down.
+
+Trade-off accepted: up to 1.5 s of feed-debug entries can be lost when the
+renderer goes away without unmounting cleanly (hard crash) or at window
+close (an `invoke` cannot be awaited past teardown). The ring's own
+durability note already accepts this.
+
+Not in scope: the main-side append path (`feedDebugLog.ts`) and the
+per-frame `runtimes` replacement itself, which is a separate structural
+item. Two pre-existing durability bugs found in review are tracked
+separately: #770 (soft reload restarts ids below the persisted cursor) and
+#771 (the fail-closed stat path resolves instead of rejecting).
+
+## Verification
+
+- `feedDebugFlushPolicy.test.ts`: immediate on first batch and after a
+  quiet period; timer for the remainder of the interval inside it; forced
+  flush at the count ceiling and at the byte ceiling; nothing while an
+  append is in flight.
+- `useFeedDebugPersist.renderer.test.tsx` (fake timers, stubbed
+  `window.api.appendFeedDebugLog`): rapid runtimes replacements produce one
+  append immediately and one more after the interval carrying every entry
+  that arrived in between; entries arriving while an append is in flight
+  are paced on resolve, not drained; the byte ceiling forces a flush; a
+  failed append leaves the entries pending and retries after the interval;
+  a removed session's trailing entries are flushed at once, or once its
+  in-flight append resolves; unmount clears the timer.
+- `npx tsc -b`.

src/main/ipc/debug.ts

@@ -16,9 +16,9 @@ import type { LifecycleIpcDiagnostics } from '@main/ipc/lifecycle.js'
 // Debug-panel IPC.
 //
 // Two endpoints:
-//   - debug:append-feed-log — streaming, fire-and-forget batches from
-//     the FeedDebugPanel flush timer. Serialized per-session in the
-//     storage module; this handler just validates shape and forwards.
+//   - debug:append-feed-log — paced batches from the renderer's
+//     persistence hook (useFeedDebugPersist, #748). Serialized per-session
+//     in the storage module; this handler just validates shape and forwards.
 //   - debug:save-bundle — one-shot, user-triggered from the "Save
 //     Debug Logs" command palette entry. Renderer assembles the bundle
 //     (state + feed-debug + proxy semantic + html raw/clean) and we

src/renderer/src/session-runtime/feedDebug.ts

@@ -10,8 +10,10 @@ import { estimateJsonBytes } from '@renderer/session-runtime/liveEntryWindow'
 // (screen_update, process_state, submit, jsonl_entries, SEM, …)
 // appends one entry here, capped at FEED_DEBUG_LOG_CAP entries AND
 // FEED_DEBUG_LOG_MAX_BYTES. The FeedDebugPanel renders this in realtime;
-// the same entries are shipped to main/storage/feedDebugLog.ts every tick
-// to be written to disk (per-session JSONL under STATE_DIR/feed-debug/).
+// the same entries are shipped to main/storage/feedDebugLog.ts in paced
+// batches (useFeedDebugPersist, #748: at most one append per session per
+// 1.5 s, sooner at a count/byte ceiling, immediately when a session is
+// removed) to be written to disk (per-session JSONL under STATE_DIR/feed-debug/).
 //
 // Why cap the in-memory array: long-running sessions could
 // accumulate tens of thousands of entries, bloating the runtime map
@@ -33,10 +35,12 @@ const FEED_DEBUG_LOG_CAP = 500
 // entry window. 4 MiB is generous for small records (500 × a few hundred
 // bytes never gets near it) and only bites when payloads are large, which is
 // exactly the case that needs bounding. Disk persistence is best-effort (one
-// in-flight append batch per session; entries evicted before it resolves are
-// never written — see useFeedDebugPersist), and the byte budget narrows that
-// loss window for large records. The ring exists for the live panel, not for
-// durability; a durable buffer is a separate concern (see the header).
+// in-flight append batch per session plus a ≤1.5 s pacing window; entries
+// evicted before they are sent are never written — see useFeedDebugPersist,
+// whose byte ceiling forces a flush at a quarter of this budget), and the
+// byte budget narrows that loss window for large records. The ring exists
+// for the live panel, not for durability; a durable buffer is a separate
+// concern (see the header).
 export const FEED_DEBUG_LOG_MAX_BYTES = 4 * 1024 * 1024
 
 // A real entry always serialises to at least its id/ts/summary envelope, so a

src/renderer/src/workspace/hook/persistence/feedDebugFlushPolicy.test.ts

@@ -0,0 +1,48 @@
+import { describe, expect, it } from 'vitest'
+
+import { countPendingFeedDebug, decideFeedDebugFlush } from './feedDebugFlushPolicy'
+
+// #748: appends must be paced by time, not by runtimes replacements.
+
+describe('decideFeedDebugFlush', () => {
+  const base = { intervalMs: 1_000, maxPending: 10, maxPendingBytes: 4_096, pendingBytes: 100, inFlight: false }
+
+  it('flushes the first batch immediately and again once the interval has elapsed', () => {
+    expect(decideFeedDebugFlush({ ...base, pendingCount: 1, lastAttemptAt: null, now: 5_000 })).toEqual({ kind: 'now' })
+    expect(decideFeedDebugFlush({ ...base, pendingCount: 1, lastAttemptAt: 4_000, now: 5_000 })).toEqual({ kind: 'now' })
+  })
+
+  it('waits out the remainder of the interval for entries that follow a flush', () => {
+    expect(decideFeedDebugFlush({ ...base, pendingCount: 3, lastAttemptAt: 4_700, now: 5_000 })).toEqual({
+      kind: 'wait',
+      delayMs: 700,
+    })
+  })
+
+  it('forces a flush at the pending ceiling even inside the interval', () => {
+    expect(decideFeedDebugFlush({ ...base, pendingCount: 10, lastAttemptAt: 4_900, now: 5_000 })).toEqual({ kind: 'now' })
+  })
+
+  it('forces a flush when the pending bytes reach the byte ceiling before the count does', () => {
+    expect(
+      decideFeedDebugFlush({ ...base, pendingCount: 2, pendingBytes: 4_096, lastAttemptAt: 4_900, now: 5_000 }),
+    ).toEqual({ kind: 'now' })
+  })
+
+  it('does nothing while an append is unresolved or when nothing is pending', () => {
+    expect(decideFeedDebugFlush({ ...base, pendingCount: 50, lastAttemptAt: null, now: 5_000, inFlight: true })).toEqual({
+      kind: 'none',
+    })
+    expect(decideFeedDebugFlush({ ...base, pendingCount: 0, lastAttemptAt: null, now: 5_000 })).toEqual({ kind: 'none' })
+  })
+})
+
+describe('countPendingFeedDebug', () => {
+  it('counts only the tail newer than the persisted cursor', () => {
+    const log = [{ id: 1 }, { id: 2 }, { id: 3 }, { id: 4 }]
+    expect(countPendingFeedDebug(log, 0)).toBe(4)
+    expect(countPendingFeedDebug(log, 2)).toBe(2)
+    expect(countPendingFeedDebug(log, 4)).toBe(0)
+    expect(countPendingFeedDebug([], 0)).toBe(0)
+  })
+})

src/renderer/src/workspace/hook/persistence/feedDebugFlushPolicy.ts

@@ -0,0 +1,85 @@
+// When to ship pending feed-debug entries to main (#748).
+//
+// WHY a policy at all: `useFeedDebugPersist` runs on every `runtimes`
+// replacement, which happens dozens of times per second while a turn
+// streams. Flushing whenever there is something pending made the append
+// cadence follow the streaming cadence — 8,649–10,159 `debug:append-feed-log`
+// invokes in a 77-minute run, 20/s in bursts, each one a `writeFile(flag:'a')`
+// and a retention-prune schedule on the main thread (p95 352 ms, max 1.2 s on
+// the Sep 1 run). The entries are diagnostics; nothing reads them within a
+// second of being written. Batching them by time turns that into ≤ 1 append
+// per session per interval without touching the cursors that carry the
+// retry/durability semantics.
+//
+// WHY the first batch after a quiet period goes out immediately: the entry
+// that explains a bad paint is usually the first one after silence, and a
+// "Save Debug Logs" right after seeing it should find it on disk. The timer
+// only paces what FOLLOWS a flush.
+//
+// WHY two ceilings, count AND bytes: the ring is byte-capped at 4 MiB (#722)
+// and evicts from the head, so an entry that waits on the timer can be
+// evicted before it is ever persisted — a loss the immediate-flush version
+// could only suffer during one in-flight append. Count alone does not bound
+// that: the #722 shape is a few hundred KB per `visible_rows` entry, where
+// twenty entries already exceed the ring. A byte ceiling at a quarter of the
+// ring forces the flush long before eviction can reach unpersisted entries
+// at any realistic rate, and keeps one append from carrying a
+// multi-megabyte batch.
+//
+// WHY `lastAttemptAt` and not `lastSuccessAt`: a rejected append (main not
+// ready, disk full) must not turn the streaming cadence back into a retry
+// storm. Counting the failed attempt as a flush rate-limits retries to the
+// same interval; the entries stay pending because the persisted cursor only
+// advances on success.
+
+export const FEED_DEBUG_FLUSH_INTERVAL_MS = 1_500
+export const FEED_DEBUG_FLUSH_MAX_PENDING = 256
+export const FEED_DEBUG_FLUSH_MAX_PENDING_BYTES = 1024 * 1024
+
+export type FeedDebugFlushDecision =
+  | { kind: 'now' }
+  | { kind: 'wait'; delayMs: number }
+  | { kind: 'none' }
+
+export type FeedDebugFlushInput = {
+  pendingCount: number
+  /** Estimated JSON bytes of the pending entries (the ring's own estimate). */
+  pendingBytes: number
+  /** Epoch ms of the last append attempt for this session, or null. */
+  lastAttemptAt: number | null
+  now: number
+  /** An append IPC is unresolved; the resolve path re-runs the policy. */
+  inFlight: boolean
+  intervalMs?: number
+  maxPending?: number
+  maxPendingBytes?: number
+}
+
+export function decideFeedDebugFlush(input: FeedDebugFlushInput): FeedDebugFlushDecision {
+  const intervalMs = input.intervalMs ?? FEED_DEBUG_FLUSH_INTERVAL_MS
+  const maxPending = input.maxPending ?? FEED_DEBUG_FLUSH_MAX_PENDING
+  const maxPendingBytes = input.maxPendingBytes ?? FEED_DEBUG_FLUSH_MAX_PENDING_BYTES
+  if (input.pendingCount <= 0) return { kind: 'none' }
+  if (input.inFlight) return { kind: 'none' }
+  if (input.pendingCount >= maxPending) return { kind: 'now' }
+  if (input.pendingBytes >= maxPendingBytes) return { kind: 'now' }
+  if (input.lastAttemptAt === null) return { kind: 'now' }
+  const elapsed = input.now - input.lastAttemptAt
+  if (elapsed >= intervalMs) return { kind: 'now' }
+  return { kind: 'wait', delayMs: intervalMs - elapsed }
+}
+
+/** Entries with id > lastPersistedId. Ids are assigned in append order, so
+ *  scanning from the tail stops at the first persisted entry — O(pending),
+ *  not O(ring) — which matters because this runs per runtimes replacement. */
+export function countPendingFeedDebug(
+  log: ReadonlyArray<{ id: number }>,
+  lastPersistedId: number,
+): number {
+  let count = 0
+  for (let i = log.length - 1; i >= 0; i -= 1) {
+    if (log[i]!.id <= lastPersistedId) break
+    count += 1
+  }
+  return count
+}