diff --git a/lib/log.test.ts b/lib/log.test.ts index 4a794f869cebf51d68c3c1d7c43923c6c51f409a..50db951b698eed843b431b5e3216d18889534e74 100644 --- a/lib/log.test.ts +++ b/lib/log.test.ts @@ -958,6 +958,42 @@ describe("log widgets", () => { host.cancel(); }); + test("oversized buffers flush whole lines synchronously", () => { + const host = new testing.MockScreen(); + const line = "x".repeat(8191) + "\n"; + for (let i = 0; i < 7; i += 1) host.writeOutput(line); + ASSERT(host.stdout === "", "flushed before reaching the threshold"); + // crossing the threshold flushes immediately, but the trailing line + // under construction stays buffered + host.writeOutput(line + "partial"); + ASSERT(host.stdout === line.repeat(8), "whole lines were not flushed"); + host.expectFrame(0, { stdout: line.repeat(8) + "partial" }); + host.cancel(); + }); + + test("single line larger than the flush threshold still flushes", () => { + const host = new testing.MockScreen(); + const giant = "y".repeat(70000); + host.writeOutput(giant); + // no newline is buffered, so memory is bounded by flushing mid-line + host.expectFrame(null, { stdout: giant }); + host.cancel(); + }); + + test("starved redraw timer flushes on the next write", () => { + const host = new testing.MockScreen(); + host.writeOutput("one\n"); + host.expectWithoutConsume(0); + // simulate a blocked event loop: time advances but no timer fires + host.timers.time += 30; + host.writeOutput("two\n"); + ASSERT(host.stdout === "", "flushed before the starvation threshold"); + host.timers.time += 30; + host.writeOutput("three\n"); + host.expectFrame(null, { stdout: "one\ntwo\nthree\n" }); + host.cancel(); + }); + test("node host patches and restores std streams", async () => { const proc = UNWRAP(node.process); const origOut = proc.stdout.write; diff --git a/lib/log.ts b/lib/log.ts index 3ea90d86c914c2e2bb97cc76457e1cb1cb1b93a2..8f173fef3670933d7668767acf59993ad54dbd0e 100644 --- a/lib/log.ts +++ b/lib/log.ts @@ -447,6 +447,14 @@ interface WidgetState { frameTime: number; } +// thresholds for flushing the log buffer outside the redraw timer. the 0ms +// timer batches a synchronous burst of writes into one flush, but waiting on +// it is wrong in two situations: the buffer growing toward the engine string +// length limit, and a timer starved by cpu-bound work blocking the event +// loop (it may never fire). +const flushSyncBytes = 65536; +const flushSyncMs = 50; + /** * terminal widget rendering is done by specifying all system APIs up front in * an interface, creating an instance of the "widget host". @@ -863,6 +871,42 @@ export function createTerminalWidgetHost( if (last && last.err === err) last.text += chunk; else buffer.push({ text: chunk, err }); redrawSoon(0); + if (locks > 0 || rendering) return; + if (buffer.reduce((n, c) => n + c.text.length, 0) >= flushSyncBytes) { + flushSync(true); + } else if (timer && now() >= redrawTime + flushSyncMs) { + // the scheduled flush is long overdue, so the event loop is blocked; + // flushing inline keeps logs streaming through cpu-bound work + flushSync(false); + } + } + + /** + * run the redraw flush immediately instead of waiting for the timer. with + * `keepPartialLine`, text after the last buffered newline stays in the + * buffer so a line under construction is not displayed mid-way; if the + * buffer holds no newline at all, everything flushes to bound memory. + */ + function flushSync(keepPartialLine: boolean) { + let tail: typeof buffer = []; + if (keepPartialLine) { + let i = buffer.length - 1; + while (i >= 0 && !UNWRAP(buffer[i]).text.includes("\n")) i -= 1; + if (i >= 0) { + const edge = UNWRAP(buffer[i]); + const split = edge.text.lastIndexOf("\n") + 1; + tail = buffer.splice(i + 1); + if (split < edge.text.length) { + tail.unshift({ text: edge.text.slice(split), err: edge.err }); + edge.text = edge.text.slice(0, split); + } + } + } + timer?.cancel(); + timer = null; + redrawCallback(); + buffer = tail; + if (tail.length) redrawSoon(0); } return { diff --git a/lib/readme.changes.md b/lib/readme.changes.md index 79fe6eb3150dc26a6385b69a18f40865ddc595ae..2619b097185e7c8b958e95ff5c92364082b71217 100644 --- a/lib/readme.changes.md +++ b/lib/readme.changes.md @@ -17,7 +17,9 @@ - `mime`'s database contains `.eot` for embedded opentype fonts. - `async.deferred` -- `log.writeError` writes to stderr with proper logic +- `log` + - `writeError` writes to stderr with proper logic. + - buffering auto-flushes synchronously when it grows past 64k. ## v4