From d3e97f9ff0494144c136a9647a548413bcd7bae0 Mon Sep 17 00:00:00 2001 From: Jean-Baptiste Date: Fri, 2 Oct 2026 21:42:31 +0200 Subject: [PATCH 1/2] (trace): count terminal writes, batch size and atlas rebuilds A renderer that burned a core could not be diagnosed: the activity trace had nothing on the terminal render path. Add a render.stats line per session per second, gated on window.ATRACE, with chunks, writes, batch size and glyph atlas rebuilds. Off, each site is one flag read. Closes #175 --- .ai/contexts/ipc-bridge.md | 15 +++ CHANGELOG.md | 2 + docs/activity-trace.md | 24 ++++- public/terminal-manager.js | 61 +++++++++++- test/terminal-render-stats.test.js | 144 +++++++++++++++++++++++++++++ 5 files changed, 239 insertions(+), 7 deletions(-) create mode 100644 test/terminal-render-stats.test.js diff --git a/.ai/contexts/ipc-bridge.md b/.ai/contexts/ipc-bridge.md index 372de541..8e0ce769 100644 --- a/.ai/contexts/ipc-bridge.md +++ b/.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`, diff --git a/CHANGELOG.md b/CHANGELOG.md index adf866c8..e96968b8 100644 --- a/CHANGELOG.md +++ b/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) diff --git a/docs/activity-trace.md b/docs/activity-trace.md index 303452ab..d1cd73b2 100644 --- a/docs/activity-trace.md +++ b/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, for a session that is not displayed: accumulated, never parsed), `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?** `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 diff --git a/public/terminal-manager.js b/public/terminal-manager.js index 3912ee66..0683ca1a 100644 --- a/public/terminal-manager.js +++ b/public/terminal-manager.js @@ -412,6 +412,46 @@ function isHiddenSingleViewSession(sessionId) { return !(entry && entry.panelMounted); } +// Render-path counters, reported through the activity trace only. +// 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 +466,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 +780,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 +790,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 +1105,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); diff --git a/test/terminal-render-stats.test.js b/test/terminal-render-stats.test.js new file mode 100644 index 00000000..3be67acc --- /dev/null +++ b/test/terminal-render-stats.test.js @@ -0,0 +1,144 @@ +// Render-path counters (issue #175): writes, batch size and atlas rebuilds, +// reported as one `render.stats` activity-trace line per session per interval. +// see docs/activity-trace.md "render.stats" + +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(); + } +}); From 89bcd6a3e3c9d77a2e89074060e98deb71f4ea50 Mon Sep 17 00:00:00 2001 From: Jean-Baptiste Date: Fri, 2 Oct 2026 21:50:16 +0200 Subject: [PATCH 2/2] (trace): cover replay, two sessions and entry-less data in render.stats Tests for the reveal replay write, separate per-session counts and data for a session without a terminal entry. Trim the comments and document hiddenChunks, the line volume and a rekey straddling a window. --- docs/activity-trace.md | 4 +-- public/terminal-manager.js | 1 - test/terminal-render-stats.test.js | 58 +++++++++++++++++++++++++++--- 3 files changed, 56 insertions(+), 7 deletions(-) diff --git a/docs/activity-trace.md b/docs/activity-trace.md index d1cd73b2..0e79c950 100644 --- a/docs/activity-trace.md +++ b/docs/activity-trace.md @@ -143,7 +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, for a session that is not displayed: accumulated, never parsed), `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) | +| `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` | @@ -152,7 +152,7 @@ Probes that only record an observation (`osc.title`, `osc.progress`, ## What to look for -**Is a terminal burning CPU legitimately?** `render.stats` has no line for a +**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 diff --git a/public/terminal-manager.js b/public/terminal-manager.js index 0683ca1a..5997afd7 100644 --- a/public/terminal-manager.js +++ b/public/terminal-manager.js @@ -412,7 +412,6 @@ function isHiddenSingleViewSession(sessionId) { return !(entry && entry.panelMounted); } -// Render-path counters, reported through the activity trace only. // see docs/activity-trace.md "render.stats" const RENDER_STATS_INTERVAL_MS = 1000; const renderStats = new Map(); diff --git a/test/terminal-render-stats.test.js b/test/terminal-render-stats.test.js index 3be67acc..bb299379 100644 --- a/test/terminal-render-stats.test.js +++ b/test/terminal-render-stats.test.js @@ -1,7 +1,3 @@ -// Render-path counters (issue #175): writes, batch size and atlas rebuilds, -// reported as one `render.stats` activity-trace line per session per interval. -// see docs/activity-trace.md "render.stats" - const test = require('node:test'); const assert = require('node:assert'); const { setupTerminalDom } = require('./terminal-manager-harness'); @@ -142,3 +138,57 @@ test('a trace switched off mid-interval drops the report instead of sending it', 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(); + } +});