Skip to content

perf: make log streaming fast under output bursts - #131

Merged
PhantomDave merged 4 commits into
mainfrom
perf/log-streaming
Oct 22, 2026
Merged

PhantomDave merged 4 commits into
mainfrom
perf/log-streaming

Conversation

@PhantomDave

Copy link
Copy Markdown
Owner

Logs often took seconds to show up. Rendering a backlog was never the slow part (500 lines render in ~100ms); the time went to output bursts and to buffered child output. Four fixes, one commit each:

  1. perf(core): the server stayed blocked for the whole burst. Each line was its own autocommit INSERT (prepared again every time), and pumpStream read already-buffered pipe chunks as microtasks, so a burst ran in a single event-loop turn. Lines are now buffered and written once per turn in one transaction with a cached statement. The stored rows (ids and session_id included) are still what the broadcaster publishes, and close() flushes pending lines before the DB closes. pumpStream yields with setImmediate after each chunk. The logs_fts trigger stays: with batching alone the burst is well under target, so grep keeps working as it does now.
  2. perf(ui): the viewer froze during a live burst. SSE entries are applied once per animation frame. mergeLogs appends directly when ids follow what's held and only dedups and sorts when they overlap (history fetch vs SSE replay). The viewer keeps the newest 5000 lines and says older output is in History. Rows are memoized. Auto-scroll now follows the array instead of its length, because the length stops changing once the cap is reached.
  3. perf(core): history queries scanned the timestamp index. Adds idx_logs_process (process_id, id) and orders history by id (insertion order), so the query reads only that process's rows. idx_logs_command (command_id) already ends in the rowid, so it needed no change. Building the index on an existing 1M-row DB takes ~0.3s, once, at startup.
  4. fix(core): Python output arrived in 8KB blocks. PYTHONUNBUFFERED=1 is now the lowest env layer, under process.env, so every other layer can override it (an empty value turns it off). Documented in docs/CONFIG.md.

Before / after

Compiled sidecar + built UI, headless Chromium, Linux.

Benchmark Before After
100k-line burst: worst /api/health latency 8946 ms 67–76 ms (3 runs)
100k-line burst: time spent in >200ms stalls 8946 ms 0 ms
Viewer open during a 20k-line burst: main-thread long tasks 8638 ms 324–593 ms (3 runs)
Viewer open during a 20k-line burst: last line visible after opening (burst starts ~4s in) 13.4 s 4.6 s
History for one process, 1M-row table (oldest pid / fresh pid with no rows) 188 ms / 188 ms 0.3 ms / 0.0 ms
Python printing a line every 200ms: first line in the viewer not within 30 s (only at exit) 0.5 s, then one line every 200ms (last of 20 at 4.3 s)

The 20k-burst "before" row uses the old UI against a core that already had fix 1, so it isolates the UI change. Against the original core it was 9.0 s of long tasks and 13.5 s to settle.

Not done here

  • listLogRuns is still ~900ms unfiltered on a 1M-row table (History page open). Grouping by process_id alone over the new index takes it to ~125ms, but a pid reused by a different command (common on macOS, where pids wrap at 99999) would then merge two runs. A covering index takes it to ~180ms but adds a five-column index to every insert. A rollup table, as the existing ponytail: note suggests, is the clean fix, but it belongs in a separate PR.
  • PTY for every runtime. Running commands under a PTY would make every runtime line-buffered, not just Python, but it merges stdout and stderr into one stream (and loses the stderr gutter). Possible follow-up.
  • The duplicate history fetch (/api/logs + SSE replay) stays. With the index both are sub-millisecond, and the fetch still gives an instant first paint.

Checks

bun test (only the two known localhost→::1 healthcheck failures), bun run lint, bun run typecheck, bun run format:check, and the run-desktop sidecar smoke before every commit.

🤖 Generated with Claude Code

Base automatically changed from fix/review-findings to main October 22, 2026 22:42
PhantomDave and others added 4 commits October 23, 2026 00:44
A process printing 100k lines left /api/health unanswered for ~9s. Each
line was its own autocommit INSERT (re-prepared every time), and
pumpStream read already-buffered pipe chunks as microtasks, so the whole
burst ran in one event-loop turn.

Log lines are now buffered and written once per turn in a single
transaction with a cached statement; the stored rows (ids and session_id
included) are what the broadcaster publishes, and close() flushes any
pending lines before the DB closes. pumpStream yields with setImmediate
after each chunk. The FTS trigger stays on the insert path: batching
alone brings the worst /api/health latency during the burst to ~70ms.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
With the viewer open while a process printed 20k lines, the browser
spent ~8.6s in main-thread long tasks: every SSE event set state,
mergeLogs rebuilt a Set and sorted the whole array per line, and every
row re-rendered (and re-parsed its ANSI codes) each time.

SSE entries are now queued and applied once per animation frame.
mergeLogs appends a batch directly when its ids follow what is held (the
live tail) and only dedups and sorts when they overlap, as with the
history fetch and the SSE replay. The viewer keeps the newest 5000 lines
and says older output is in History. Rows are memoized, and auto-scroll
follows the array rather than its length, which stops changing at the cap.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
queryLogs filtered by process_id with no index on it, so ORDER BY
timestamp DESC walked idx_logs_timestamp across every process until it
found 500 matches. On a 1M-row table a quiet or freshly started process
took ~190ms per query, and the viewer runs it twice on open (the
/api/logs fetch and the SSE replay).

Add idx_logs_process on (process_id, id) and order history by id, which
follows insertion order and matches the index, so neither the pid nor the
command filter needs a sort. The same queries now take ~0.3ms. Building
the index on an existing 1M-row database takes ~0.3s, once, at startup.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Python block-buffers stdout when it is a pipe, so a service printing a
line every 200ms showed nothing in the viewer until ~8KB had piled up
(or until it exited). PYTHONUNBUFFERED=1 is now the lowest env layer,
below process.env, so the shell, global_env, profile env and
env_overrides can all override it (an empty value turns it off).

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@PhantomDave
PhantomDave enabled auto-merge (squash) October 22, 2026 22:45
@PhantomDave
PhantomDave disabled auto-merge October 22, 2026 22:48
@PhantomDave
PhantomDave merged commit c1cb1ae into main Oct 22, 2026
12 of 13 checks passed
@PhantomDave
PhantomDave deleted the perf/log-streaming branch October 22, 2026 22:48
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant