(trace): record terminal render-path counters (#175)

.ai/contexts/ipc-bridge.md

@@ -350,6 +350,21 @@ does not claim the distinction: the sidebar tints the busy spinner violet when
 subagents are live, which asserts only that both things are true at once — see
 `docs/subagents.md`, "Live status".
 
+### Activity trace: render-path counters
+
+`render.stats` (renderer, `public/terminal-manager.js`) answers "is this
+terminal's CPU legitimate": writes, batch size and glyph-atlas rebuilds per
+session per second. It aggregates instead of tracing each write, because a
+per-chunk line would itself be the load at 30 writes a second. The counters sit
+in `renderStats`, created on the first event while `window.ATRACE` is true;
+one `setTimeout` per window, armed by that first event, emits and clears them,
+and drops them if the trace was switched off meanwhile. Nothing is armed while
+the trace is off or the session is silent. `maxBatch*` is per write, not per
+second; `atlasChanges` / `atlasCanvases` are the events that make
+`loadTerminalWebgl` repaint every visible row. Test:
+`test/terminal-render-stats.test.js`. It reports; it does not change the flush
+cap or the WebGL policy.
+
 ### Activity trace: why the main process is the only writer
 
 `activity-trace.js` + `public/activity-trace.js` + `public/activity-trace-panel.js`,

CHANGELOG.md

@@ -4,6 +4,8 @@ What changes for you in each release of Switchboard. How to write an entry: [doc
 
 ## Unreleased
 
+### New
+- With Debug mode on, the activity trace now records how hard each terminal is being drawn: once a second per session, how many writes reached it, how large they were and how often its glyph atlas was rebuilt, to tell a legitimately busy terminal from a runaway one. (#175)
 ### Changed
 - A trigger that gave up waiting for a session now says, in its result file's `reason`, when the session was blocked on a dialog such as a permission prompt or a question: for a single trigger, a chain's first wait, and a chain step whose turn never finished. Without a dialog the result is as before. (#379)
 

docs/activity-trace.md

@@ -143,6 +143,7 @@ Probes that only record an observation (`osc.title`, `osc.progress`,
 | `class.toggle` | `has-running-pty` written | `el`, `cls`, `on` |
 | `class.subagent` | A subagent's `running` / `has-running-child` / `has-busy-agents` written | `el` ids, `running` |
 | `class.render` | A full sidebar render rebuilt an item's classes from the stores | `el`, `cls` |
+| `render.stats` | Once per second per session that saw terminal activity, while the trace is on: the terminal render path's counters for that second | `ms` (the window's real length), `chunks`, `chars` (PTY data events received and their length), `hiddenChunks` (of those, received while the session's terminal is not displayed in single view: accumulated, never parsed; grid sessions never count as hidden), `writes`, `writeChars` (calls to `terminal.write`, from the 30 fps flush or a reveal replay, and what they carried), `maxBatchChunks`, `maxBatchChars` (the largest single write), `atlasChanges`, `atlasCanvases` (glyph atlas rebuilds and added atlas pages, each of which repaints every visible row) |
 | `poll.recv` | The poll reply reaches the renderer | `sinceSeq`, `entries` |
 | `reconcile.apply` / `reconcile.skip` / `reconcile.noop` | Per session in the poll reply | `backend`, `local`, `reason`, `sinceSeq`, `sessionSeq` |
 
@@ -151,6 +152,16 @@ Probes that only record an observation (`osc.title`, `osc.progress`,
 
 ## What to look for
 
+**Is a terminal burning CPU legitimately?** The volume is one line per active session per second, hidden sessions and sessions without a terminal entry included. A window that straddles a temp-to-real id rekey reports under both ids. `render.stats` has no line for a
+second in which the session saw nothing. Writes per second is `writes * 1000 /
+ms`; it cannot exceed about 30 for a displayed session, and `writeChars /
+writes` is the batch size. A high `atlasChanges` in the same seconds as the CPU
+means repaints from the glyph atlas, not parsing:
+
+```bash
+jq -c 'select(.cat=="render.stats") | {sid, w: (.writes*1000/.ms), batch: (.writeChars/(.writes|if .==0 then 1 else . end)), atlasChanges, atlasCanvases}' $TRACE
+```
+
 **Does the CLI's title still match the busy test?** The spinner glyphs are the
 CLI's private business and can change with a release. After a CLI upgrade:
 
@@ -285,10 +296,15 @@ is the OSC 0 `log.debug` line, guarded by `if (LOG_DEBUG_ON)` instead and pinned
 by `test/osc-debug-log-guards.test.js`: a packaged build logs at `info`, so it
 is inert there.
 
-Even with the trace on, no probe sits on the terminal render path: `osc.title`
-fires only for chunks carrying an OSC introducer, and `pty.input` only for
-chunks sent *to* the PTY. This matters because of
-[decision 0002](decisions/0002-discrete-steps-sidebar-animations.md): the
+Even with the trace on, no per-chunk line is written for the terminal render
+path: `osc.title` fires only for chunks carrying an OSC introducer, and
+`pty.input` only for chunks sent *to* the PTY. The render path is observed by
+`render.stats`, which counts in memory and sends one line per session per
+second. Off, each of its sites in `public/terminal-manager.js` is one
+`window.ATRACE` read: no counter object, no timer and no clock read per write.
+On, a write costs an integer increment; the one timer is armed by the first
+event of a window and is not re-armed when nothing happens. This matters because
+of [decision 0002](decisions/0002-discrete-steps-sidebar-animations.md): the
 indicators are built not to burn CPU at idle.
 
 ## Implementation notes

public/terminal-manager.js

@@ -412,6 +412,45 @@ function isHiddenSingleViewSession(sessionId) {
   return !(entry && entry.panelMounted);
 }
 
+// see docs/activity-trace.md "render.stats"
+const RENDER_STATS_INTERVAL_MS = 1000;
+const renderStats = new Map();
+let renderStatsTimer = 0;
+let renderStatsSince = 0;
+
+function renderStatFor(sessionId) {
+  let s = renderStats.get(sessionId);
+  if (!s) {
+    s = {
+      chunks: 0, chars: 0, hiddenChunks: 0, writes: 0, writeChars: 0,
+      maxBatchChunks: 0, maxBatchChars: 0, atlasChanges: 0, atlasCanvases: 0,
+    };
+    renderStats.set(sessionId, s);
+  }
+  if (!renderStatsTimer) {
+    renderStatsSince = performance.now();
+    renderStatsTimer = setTimeout(emitRenderStats, RENDER_STATS_INTERVAL_MS);
+  }
+  return s;
+}
+
+function noteRenderWrite(sessionId, chunks, chars) {
+  const s = renderStatFor(sessionId);
+  s.writes++;
+  s.writeChars += chars;
+  if (chunks > s.maxBatchChunks) s.maxBatchChunks = chunks;
+  if (chars > s.maxBatchChars) s.maxBatchChars = chars;
+}
+
+function emitRenderStats() {
+  renderStatsTimer = 0;
+  const ms = Math.round(performance.now() - renderStatsSince);
+  const pending = Array.from(renderStats);
+  renderStats.clear();
+  if (!window.ATRACE) return;
+  for (const [sid, s] of pending) window.atrace('render.stats', sid, { ms, ...s });
+}
+
 function flushTerminalBuffer(sessionId) {
   const buf = terminalWriteBuffers.get(sessionId);
   if (!buf) return;
@@ -426,6 +465,7 @@ function flushTerminalBuffer(sessionId) {
   if (!entry) return;
 
   const data = buf.chunks.join('');
+  if (window.ATRACE) noteRenderWrite(sessionId, buf.chunks.length, data.length);
   lastFlushAt.set(sessionId, performance.now());
   const wasAtBottom = isAtBottom(entry.terminal);
   const savedViewportY = entry.terminal.buffer.active.viewportY;
@@ -739,6 +779,7 @@ function replayHiddenBuffer(sessionId) {
   const entry = openSessions.get(sessionId);
   if (!entry) return; // destroySession may have removed it first
   if (acc.reset) entry.terminal.reset();
+  if (window.ATRACE) noteRenderWrite(sessionId, 1, acc.raw.length);
   entry.terminal.write(acc.raw);
 }
 
@@ -748,8 +789,15 @@ function replayHiddenBuffer(sessionId) {
 // this logic sat in untestable app.js.
 function handleTerminalData(sessionId, data) {
   const entry = openSessions.get(sessionId);
+  const hidden = !!entry && isHiddenSingleViewSession(sessionId);
+  if (window.ATRACE) {
+    const s = renderStatFor(sessionId);
+    s.chunks++;
+    s.chars += data.length;
+    if (hidden) s.hiddenChunks++;
+  }
   if (entry) {
-    if (isHiddenSingleViewSession(sessionId)) {
+    if (hidden) {
       // Fully suspended — accumulate only, never call terminal.write().
       // drainLiveBufferIntoHiddenAccumulator folds in whatever was left
       // pending from before this session became hidden (see its own
@@ -1056,8 +1104,14 @@ function loadTerminalWebgl(entry) {
     // garbled glyphs. Repaint all visible rows so they re-resolve against the
     // new atlas.
     const repaintVisible = () => entry.terminal.refresh(0, entry.terminal.rows - 1);
-    webglAddon.onChangeTextureAtlas(repaintVisible);
-    webglAddon.onAddTextureAtlasCanvas(repaintVisible);
+    webglAddon.onChangeTextureAtlas(() => {
+      if (window.ATRACE) renderStatFor(entry.session.sessionId).atlasChanges++;
+      repaintVisible();
+    });
+    webglAddon.onAddTextureAtlasCanvas(() => {
+      if (window.ATRACE) renderStatFor(entry.session.sessionId).atlasCanvases++;
+      repaintVisible();
+    });
     entry.webglAddon = webglAddon;
   } catch (e) {
     console.warn('[terminal] WebGL addon failed, falling back to DOM renderer', e);

test/terminal-render-stats.test.js

@@ -0,0 +1,194 @@
+const test = require('node:test');
+const assert = require('node:assert');
+const { setupTerminalDom } = require('./terminal-manager-harness');
+
+function setup({ on }) {
+  const h = setupTerminalDom();
+  const { window } = h;
+  const traced = [];
+  const timers = [];
+  let atlasCb = null;
+  let canvasCb = null;
+  window.ATRACE = on;
+  window.atrace = (cat, sid, fields) => { traced.push({ cat, sid, fields }); };
+  const realSetTimeout = window.setTimeout.bind(window);
+  window.setTimeout = (fn, ms) => {
+    if (ms !== 1000) return realSetTimeout(fn, ms);
+    timers.push({ fn, ms });
+    return timers.length;
+  };
+  window.WebglAddon = {
+    WebglAddon: class {
+      dispose() {}
+      onContextLoss() {}
+      onChangeTextureAtlas(cb) { atlasCb = cb; }
+      onAddTextureAtlasCanvas(cb) { canvasCb = cb; }
+    },
+  };
+  window.activeSessionId = 's1';
+  window.createTerminalEntry({ sessionId: 's1' });
+  const stats = () => traced.filter((t) => t.cat === 'render.stats');
+  return {
+    ...h, traced, timers, stats, realSetTimeout,
+    fireAtlas: () => atlasCb(),
+    fireCanvas: () => canvasCb(),
+  };
+}
+
+test('with the trace on, writes, batch size and chars are counted and reported once per interval', () => {
+  const t = setup({ on: true });
+  try {
+    t.window.handleTerminalData('s1', 'abc');
+    t.window.handleTerminalData('s1', 'de');
+    t.window.flushTerminalBuffer('s1');
+    t.window.handleTerminalData('s1', 'f');
+    t.window.flushTerminalBuffer('s1');
+
+    assert.strictEqual(t.stats().length, 0, 'nothing is sent before the interval ends');
+    assert.strictEqual(t.timers.length, 1, 'one interval timer is armed for all of it');
+    t.timers[0].fn();
+
+    const lines = t.stats();
+    assert.strictEqual(lines.length, 1);
+    assert.strictEqual(lines[0].sid, 's1');
+    const f = lines[0].fields;
+    assert.strictEqual(f.chunks, 3);
+    assert.strictEqual(f.chars, 6);
+    assert.strictEqual(f.writes, 2);
+    assert.strictEqual(f.writeChars, 6);
+    assert.strictEqual(f.maxBatchChunks, 2);
+    assert.strictEqual(f.maxBatchChars, 5);
+    assert.strictEqual(f.hiddenChunks, 0);
+    assert.strictEqual(typeof f.ms, 'number');
+  } finally {
+    t.destroy();
+  }
+});
+
+test('atlas rebuilds and added atlas canvases are counted separately', () => {
+  const t = setup({ on: true });
+  try {
+    t.fireAtlas();
+    t.fireAtlas();
+    t.fireCanvas();
+    t.timers[0].fn();
+    const f = t.stats()[0].fields;
+    assert.strictEqual(f.atlasChanges, 2);
+    assert.strictEqual(f.atlasCanvases, 1);
+  } finally {
+    t.destroy();
+  }
+});
+
+test('a chunk for a hidden session is counted as hidden and writes nothing', () => {
+  const t = setup({ on: true });
+  try {
+    t.window.activeSessionId = 'other';
+    t.window.handleTerminalData('s1', 'zz');
+    t.timers[0].fn();
+    const f = t.stats()[0].fields;
+    assert.strictEqual(f.hiddenChunks, 1);
+    assert.strictEqual(f.chunks, 1);
+    assert.strictEqual(f.writes, 0);
+  } finally {
+    t.destroy();
+  }
+});
+
+test('a new interval starts after a report, and an empty interval reports nothing', () => {
+  const t = setup({ on: true });
+  try {
+    t.window.handleTerminalData('s1', 'a');
+    t.timers[0].fn();
+    assert.strictEqual(t.timers.length, 1, 'no timer is re-armed while nothing happens');
+    t.window.handleTerminalData('s1', 'b');
+    assert.strictEqual(t.timers.length, 2);
+    t.timers[1].fn();
+    assert.strictEqual(t.stats().length, 2);
+    assert.strictEqual(t.stats()[1].fields.chunks, 1, 'counters restart from zero');
+  } finally {
+    t.destroy();
+  }
+});
+
+test('with the trace off nothing is counted, no timer is armed, and the data still flows', () => {
+  const t = setup({ on: false });
+  try {
+    t.window.handleTerminalData('s1', 'abc');
+    t.window.flushTerminalBuffer('s1');
+    t.fireAtlas();
+    assert.strictEqual(t.timers.length, 0, 'no timer');
+    assert.strictEqual(t.inCtx('renderStats.size'), 0, 'no per-session record allocated');
+    assert.strictEqual(t.traced.length, 0);
+    assert.deepStrictEqual(t.spies.writes, ['abc'], 'the write itself is unchanged');
+  } finally {
+    t.destroy();
+  }
+});
+
+test('a trace switched off mid-interval drops the report instead of sending it', () => {
+  const t = setup({ on: true });
+  try {
+    t.window.handleTerminalData('s1', 'a');
+    t.window.ATRACE = false;
+    t.timers[0].fn();
+    assert.strictEqual(t.stats().length, 0);
+    assert.strictEqual(t.inCtx('renderStats.size'), 0);
+  } finally {
+    t.destroy();
+  }
+});
+
+test('revealing a hidden session counts the replay write', () => {
+  const t = setup({ on: true });
+  try {
+    t.window.activeSessionId = 'other';
+    t.window.handleTerminalData('s1', 'hidden-data');
+    t.window.replayHiddenBuffer('s1');
+    t.timers[0].fn();
+    const f = t.stats()[0].fields;
+    assert.strictEqual(f.writes, 1);
+    assert.strictEqual(f.writeChars, 'hidden-data'.length);
+    assert.strictEqual(f.hiddenChunks, 1);
+  } finally {
+    t.destroy();
+  }
+});
+
+test('two sessions in one window report two lines with separate counts', () => {
+  const t = setup({ on: true });
+  try {
+    t.window.createTerminalEntry({ sessionId: 's2' });
+    t.window.handleTerminalData('s1', 'a');
+    t.window.handleTerminalData('s2', 'bb');
+    t.window.handleTerminalData('s2', 'cc');
+    t.timers[0].fn();
+    const lines = t.stats();
+    assert.strictEqual(t.timers.length, 1, 'one timer serves both sessions');
+    assert.strictEqual(lines.length, 2);
+    const bySid = Object.fromEntries(lines.map((l) => [l.sid, l.fields]));
+    assert.strictEqual(bySid.s1.chunks, 1);
+    assert.strictEqual(bySid.s1.chars, 1);
+    assert.strictEqual(bySid.s2.chunks, 2);
+    assert.strictEqual(bySid.s2.chars, 4);
+  } finally {
+    t.destroy();
+  }
+});
+
+test('data for a session with no entry does not throw, is counted as received and never as hidden', () => {
+  const t = setup({ on: true });
+  try {
+    t.window.activeSessionId = 'other';
+    assert.doesNotThrow(() => t.window.handleTerminalData('ghost', 'xyz'));
+    t.timers[0].fn();
+    const f = t.stats()[0].fields;
+    assert.strictEqual(t.stats()[0].sid, 'ghost');
+    assert.strictEqual(f.chunks, 1);
+    assert.strictEqual(f.chars, 3);
+    assert.strictEqual(f.hiddenChunks, 0);
+    assert.strictEqual(f.writes, 0);
+  } finally {
+    t.destroy();
+  }
+});