authorgravatar for git@paperclover.netclover caruso <git@paperclover.net> 2026-06-12 18:25:42-07:00
committergravatar for git@paperclover.netclover caruso <git@paperclover.net> 2026-06-15 12:49:48-07:00
logbd99670fb91ecff5cbdb1a33ecbf927cdb3e6556
tree23ce0378540ee06cf992ee1fd4cefa3163290620
parent333b8a7a5c68ab8ab1917a6192022b0f96c46823
signature Signed by SSH key SHA256:cOKiuRFOeSRxne6EWgHtdQQSlBxjOXm2hOCFnCdLQbQ

feat(lib/log): flush the log buffer on size and time thresholds

closes #50, closes #31. the 0ms redraw timer batches write bursts, but waiting on it is wrong in two cases: a buffer growing toward the engine string length limit (flush at 64k, keeping the trailing partial line buffered so a line under construction is not displayed mid-way), and a timer starved by cpu-bound work blocking the event loop (a write made 50ms after a flush should have run flushes inline, so logs keep streaming during long computations).

3 files changed, 83 insertions(+), 1 deletions(-)

lib/log.test.ts+36
...@@ -958,6 +958,42 @@ describe("log widgets", () => {...@@ -958,6 +958,42 @@ describe("log widgets", () => {
958 host.cancel();958 host.cancel();
959 });959 });
960960
961 test("oversized buffers flush whole lines synchronously", () => {
962 const host = new testing.MockScreen();
963 const line = "x".repeat(8191) + "\n";
964 for (let i = 0; i < 7; i += 1) host.writeOutput(line);
965 ASSERT(host.stdout === "", "flushed before reaching the threshold");
966 // crossing the threshold flushes immediately, but the trailing line
967 // under construction stays buffered
968 host.writeOutput(line + "partial");
969 ASSERT(host.stdout === line.repeat(8), "whole lines were not flushed");
970 host.expectFrame(0, { stdout: line.repeat(8) + "partial" });
971 host.cancel();
972 });
973
974 test("single line larger than the flush threshold still flushes", () => {
975 const host = new testing.MockScreen();
976 const giant = "y".repeat(70000);
977 host.writeOutput(giant);
978 // no newline is buffered, so memory is bounded by flushing mid-line
979 host.expectFrame(null, { stdout: giant });
980 host.cancel();
981 });
982
983 test("starved redraw timer flushes on the next write", () => {
984 const host = new testing.MockScreen();
985 host.writeOutput("one\n");
986 host.expectWithoutConsume(0);
987 // simulate a blocked event loop: time advances but no timer fires
988 host.timers.time += 30;
989 host.writeOutput("two\n");
990 ASSERT(host.stdout === "", "flushed before the starvation threshold");
991 host.timers.time += 30;
992 host.writeOutput("three\n");
993 host.expectFrame(null, { stdout: "one\ntwo\nthree\n" });
994 host.cancel();
995 });
996
961 test("node host patches and restores std streams", async () => {997 test("node host patches and restores std streams", async () => {
962 const proc = UNWRAP(node.process);998 const proc = UNWRAP(node.process);
963 const origOut = proc.stdout.write;999 const origOut = proc.stdout.write;
lib/log.ts+44
...@@ -447,6 +447,14 @@ interface WidgetState {...@@ -447,6 +447,14 @@ interface WidgetState {
447 frameTime: number;447 frameTime: number;
448}448}
449449
450// thresholds for flushing the log buffer outside the redraw timer. the 0ms
451// timer batches a synchronous burst of writes into one flush, but waiting on
452// it is wrong in two situations: the buffer growing toward the engine string
453// length limit, and a timer starved by cpu-bound work blocking the event
454// loop (it may never fire).
455const flushSyncBytes = 65536;
456const flushSyncMs = 50;
457
450/**458/**
451 * terminal widget rendering is done by specifying all system APIs up front in459 * terminal widget rendering is done by specifying all system APIs up front in
452 * an interface, creating an instance of the "widget host".460 * an interface, creating an instance of the "widget host".
...@@ -863,6 +871,42 @@ export function createTerminalWidgetHost(...@@ -863,6 +871,42 @@ export function createTerminalWidgetHost(
863 if (last && last.err === err) last.text += chunk;871 if (last && last.err === err) last.text += chunk;
864 else buffer.push({ text: chunk, err });872 else buffer.push({ text: chunk, err });
865 redrawSoon(0);873 redrawSoon(0);
874 if (locks > 0 || rendering) return;
875 if (buffer.reduce((n, c) => n + c.text.length, 0) >= flushSyncBytes) {
876 flushSync(true);
877 } else if (timer && now() >= redrawTime + flushSyncMs) {
878 // the scheduled flush is long overdue, so the event loop is blocked;
879 // flushing inline keeps logs streaming through cpu-bound work
880 flushSync(false);
881 }
882 }
883
884 /**
885 * run the redraw flush immediately instead of waiting for the timer. with
886 * `keepPartialLine`, text after the last buffered newline stays in the
887 * buffer so a line under construction is not displayed mid-way; if the
888 * buffer holds no newline at all, everything flushes to bound memory.
889 */
890 function flushSync(keepPartialLine: boolean) {
891 let tail: typeof buffer = [];
892 if (keepPartialLine) {
893 let i = buffer.length - 1;
894 while (i >= 0 && !UNWRAP(buffer[i]).text.includes("\n")) i -= 1;
895 if (i >= 0) {
896 const edge = UNWRAP(buffer[i]);
897 const split = edge.text.lastIndexOf("\n") + 1;
898 tail = buffer.splice(i + 1);
899 if (split < edge.text.length) {
900 tail.unshift({ text: edge.text.slice(split), err: edge.err });
901 edge.text = edge.text.slice(0, split);
902 }
903 }
904 }
905 timer?.cancel();
906 timer = null;
907 redrawCallback();
908 buffer = tail;
909 if (tail.length) redrawSoon(0);
866 }910 }
867911
868 return {912 return {
lib/readme.changes.md+3-1
...@@ -17,7 +17,9 @@...@@ -17,7 +17,9 @@
1717
18- `mime`'s database contains `.eot` for embedded opentype fonts.18- `mime`'s database contains `.eot` for embedded opentype fonts.
19- `async.deferred`19- `async.deferred`
20- `log.writeError` writes to stderr with proper logic20- `log`
21 - `writeError` writes to stderr with proper logic.
22 - buffering auto-flushes synchronously when it grows past 64k.
2123
22## v424## v4
2325