Eliminate spiky terminal lag under load (#1500)
* Eliminate spiky terminal lag under load
Terminal output stuttered during heavy output and when the daemon was
busy. Two compounding causes, both confirmed by measurement:
- Every 256KB of output, the daemon dropped pending frames and re-sent a
full cell-grid snapshot (cloned across IPC, stringified to JSON) — a
10MB build did this ~40 times. The snapshot fallback is now gated on
real client backpressure (ws bufferedAmount), so a client that keeps
draining streams continuously and never pays the snapshot tax. This
also removes the periodic GC hitch the churn caused.
- Per-chunk overhead on the shared event loop: one IPC message per pty
chunk, a duplicate input-mode regex scan on the daemon main loop, a
double JSON.stringify per outbound message, and 16KB string realloc
per chunk. Output now coalesces in the worker before IPC (leading-edge
so keystrokes still echo immediately), the duplicate scan is gone, and
the client feeds xterm back-to-back instead of one render tick a frame.
Adds eventLoopDelay percentiles to ws_runtime_metrics for main-loop
stall visibility, plus a reproducible Node benchmark (no port 6767).
Measured: echo p50 7.7ms to 2.3ms; a 2MB burst now streams fully with
zero snapshots; loop-stall spikes 100-173ms to 2ms.
* Guard trace-level check against partial logger stubs
The isLevelEnabled gate added for the emit() perf fix crashed every
session test that injects a hand-rolled logger stub (10 of them omit
isLevelEnabled). Real pino loggers always provide it; optional-chaining
keeps the perf gate intact in production and no-ops on stubs.
* Make recent-output exit-summary test deterministic
The added test self-exited the child immediately after writing 3000
lines, then asserted the newest line was in the exit summary — but the
summary reads the headless xterm buffer, which parses writes
asynchronously, so a loaded CI runner saw a stale buffer (line-2707 not
line-2999). Keep the process alive and poll the parsed buffer until the
final line lands before killing, removing the race.
* Skip ConPTY-fragile worker terminal tests on Windows
The coalescing and input-mode-preamble tests assert byte-contiguous PTY
output and an exact kitty-escape round-trip. Windows ConPTY injects
repaint sequences between writes and normalizes the escape, so both time
out there while passing on Linux/macOS. Gate them with skipIf(win32),
matching the existing terminal-test convention for PTY-sensitive cases.
* Apply terminal barriers immediately when no writes are pending
A barrier op (snapshot/restore/clear) only needs the sentinel-write gate
to wait out plain writes still parsing in xterm's buffer. When none are
ungated — at mount, or right after another barrier — the sentinel cost a
wasted parse cycle, adding latency to the first snapshot/restore on the
hot first-paint path. Track ungated writes with a flag and skip the
sentinel when there's nothing to gate.
* Fix mobile startup saved-host e2e
* Unskip Windows worker terminal coverage
* Tighten worker coalescing assertion
* Reset terminal ungated writes on unmount
* Fix terminal regressions found in adversarial review
Three issues this PR's terminal changes introduced:
- Worker snapshot could duplicate coalesced output. getTerminalState
snapshotted without flushing the worker output coalescer, so a batch
spanning the snapshot point carried a revision past it and the
controller's dedup couldn't drop it — the client saw the bytes twice.
Flush before snapshotting.
- Relay clients lost backpressure protection. The snapshot fallback was
gated on bufferedAmount, which the multiplexed relay socket reports as
absent; that read as 0 ("keeping up") so a slow relay client never
caught up via a snapshot. Distinguish "no signal" (null) from 0 and
keep the unconditional byte-threshold fallback for signal-less
transports, preserving the pre-change relay behavior.
- Recent-output buffer was no longer a hard cap. A single chunk larger
than the limit was retained whole; slice its tail.
Documents the live-restore preamble gap (unreachable: no client sends
restore mode "live").
* Skip input-mode preamble test on Windows ConPTY
CI confirmed Windows ConPTY normalizes away the kitty keyboard escape
the child writes, so it never reaches the worker's input-mode tracker
and the preamble stays empty — the test times out. ConPTY can't exercise
this contract; the coalescing test (file-gated, line-oriented) stays on
all platforms, only the preamble assertion is gated to Linux/macOS.
This commit is contained in:
@@ -3,6 +3,7 @@ import { TerminalOutputCoalescer } from "./terminal-output-coalescer.js";
|
||||
|
||||
function createHarness() {
|
||||
let nextTimer = 1;
|
||||
let now = 1000;
|
||||
const scheduled = new Map<number, { callback: () => void; delayMs: number }>();
|
||||
const flushes: Array<{ payload: string; chars: number; bytes: number }> = [];
|
||||
const coalescer = new TerminalOutputCoalescer({
|
||||
@@ -17,6 +18,7 @@ function createHarness() {
|
||||
scheduled.delete(id);
|
||||
}) as typeof clearTimeout,
|
||||
},
|
||||
now: () => now,
|
||||
onFlush: ({ payload, chars, bytes }) => {
|
||||
flushes.push({ payload: payload.toString("utf8"), chars, bytes });
|
||||
},
|
||||
@@ -26,6 +28,9 @@ function createHarness() {
|
||||
coalescer,
|
||||
flushes,
|
||||
scheduled,
|
||||
advance(ms: number) {
|
||||
now += ms;
|
||||
},
|
||||
runScheduled() {
|
||||
const callbacks = Array.from(scheduled.values());
|
||||
scheduled.clear();
|
||||
@@ -37,10 +42,22 @@ function createHarness() {
|
||||
}
|
||||
|
||||
describe("TerminalOutputCoalescer", () => {
|
||||
test("coalesces output into one 5ms flush window", () => {
|
||||
const { coalescer, flushes, runScheduled, scheduled } = createHarness();
|
||||
test("flushes the first chunk immediately on the leading edge", () => {
|
||||
const { coalescer, flushes, scheduled } = createHarness();
|
||||
|
||||
coalescer.handle("a");
|
||||
|
||||
// No timer scheduled: the leading-edge flush happened synchronously.
|
||||
expect(scheduled.size).toBe(0);
|
||||
expect(flushes).toEqual([{ payload: "a", chars: 1, bytes: 1 }]);
|
||||
});
|
||||
|
||||
test("coalesces a burst that follows the leading-edge flush into one trailing flush", () => {
|
||||
const { coalescer, flushes, runScheduled, scheduled } = createHarness();
|
||||
|
||||
// First chunk flushes immediately (leading edge).
|
||||
coalescer.handle("a");
|
||||
// Subsequent chunks within the window accumulate behind a trailing timer.
|
||||
coalescer.handle("b");
|
||||
coalescer.handle("é");
|
||||
|
||||
@@ -48,32 +65,86 @@ describe("TerminalOutputCoalescer", () => {
|
||||
expect(Array.from(scheduled.values())).toEqual([
|
||||
{ callback: expect.any(Function), delayMs: 5 },
|
||||
]);
|
||||
expect(flushes).toEqual([]);
|
||||
expect(flushes).toEqual([{ payload: "a", chars: 1, bytes: 1 }]);
|
||||
|
||||
runScheduled();
|
||||
|
||||
expect(flushes).toEqual([{ payload: "abé", chars: 3, bytes: 4 }]);
|
||||
expect(flushes).toEqual([
|
||||
{ payload: "a", chars: 1, bytes: 1 },
|
||||
{ payload: "bé", chars: 2, bytes: 3 },
|
||||
]);
|
||||
});
|
||||
|
||||
test("flushes immediately again once the window has elapsed", () => {
|
||||
const { coalescer, flushes, advance, scheduled } = createHarness();
|
||||
|
||||
coalescer.handle("a");
|
||||
expect(flushes).toEqual([{ payload: "a", chars: 1, bytes: 1 }]);
|
||||
|
||||
advance(5);
|
||||
coalescer.handle("b");
|
||||
|
||||
expect(scheduled.size).toBe(0);
|
||||
expect(flushes).toEqual([
|
||||
{ payload: "a", chars: 1, bytes: 1 },
|
||||
{ payload: "b", chars: 1, bytes: 1 },
|
||||
]);
|
||||
});
|
||||
|
||||
test("manual flush drains pending output and cancels the scheduled flush", () => {
|
||||
const { coalescer, flushes, runScheduled, scheduled } = createHarness();
|
||||
|
||||
// Leading-edge flush, then accumulate a burst behind the trailing timer.
|
||||
coalescer.handle("hello");
|
||||
coalescer.handle(" world");
|
||||
coalescer.flush();
|
||||
runScheduled();
|
||||
|
||||
expect(scheduled.size).toBe(0);
|
||||
expect(flushes).toEqual([{ payload: "hello", chars: 5, bytes: 5 }]);
|
||||
expect(flushes).toEqual([
|
||||
{ payload: "hello", chars: 5, bytes: 5 },
|
||||
{ payload: " world", chars: 6, bytes: 6 },
|
||||
]);
|
||||
});
|
||||
|
||||
test("dispose drops pending output", () => {
|
||||
const { coalescer, flushes, runScheduled, scheduled } = createHarness();
|
||||
|
||||
// First chunk flushes on the leading edge; second one stays pending.
|
||||
coalescer.handle("done");
|
||||
coalescer.handle("pending");
|
||||
coalescer.dispose();
|
||||
runScheduled();
|
||||
|
||||
expect(scheduled.size).toBe(0);
|
||||
expect(flushes).toEqual([{ payload: "done", chars: 4, bytes: 4 }]);
|
||||
});
|
||||
|
||||
test("markFlushed keeps the next chunk on the trailing path", () => {
|
||||
const { coalescer, flushes, runScheduled, scheduled } = createHarness();
|
||||
|
||||
// Simulate a frame emitted out-of-band (e.g. a snapshot) right before output.
|
||||
coalescer.markFlushed();
|
||||
coalescer.handle("post-snapshot");
|
||||
|
||||
// No immediate flush: the chunk waits for the trailing timer.
|
||||
expect(scheduled.size).toBe(1);
|
||||
expect(flushes).toEqual([]);
|
||||
|
||||
runScheduled();
|
||||
expect(flushes).toEqual([{ payload: "post-snapshot", chars: 13, bytes: 13 }]);
|
||||
});
|
||||
|
||||
test("preserves ordering across leading and trailing flushes", () => {
|
||||
const { coalescer, flushes, runScheduled, advance } = createHarness();
|
||||
|
||||
coalescer.handle("1");
|
||||
coalescer.handle("2");
|
||||
coalescer.handle("3");
|
||||
runScheduled();
|
||||
advance(5);
|
||||
coalescer.handle("4");
|
||||
|
||||
expect(flushes.map((f) => f.payload)).toEqual(["1", "23", "4"]);
|
||||
});
|
||||
});
|
||||
|
||||
Reference in New Issue
Block a user