diff --git a/.changeset/pi-tui-render-profiler.md b/.changeset/pi-tui-render-profiler.md new file mode 100644 index 0000000000..e42346e133 --- /dev/null +++ b/.changeset/pi-tui-render-profiler.md @@ -0,0 +1,5 @@ +--- +"@moonshot-ai/pi-tui": patch +--- + +Add an opt-in render profiler that records per-frame render cost and stdout write timing for diagnosing terminal render stutter. diff --git a/packages/pi-tui/src/render-profiler.ts b/packages/pi-tui/src/render-profiler.ts new file mode 100644 index 0000000000..afbb15fcad --- /dev/null +++ b/packages/pi-tui/src/render-profiler.ts @@ -0,0 +1,156 @@ +/** + * Opt-in render profiler for diagnosing TUI render and stdout-write cost. + * + * Enabled via the `PI_TUI_RENDER_PROFILE` environment variable: + * - unset / empty -> disabled (near-zero overhead) + * - "1" / "true" -> write JSONL to ~/.pi/agent/pi-render-profile.jsonl + * - any other value -> treated as the output file path + * + * Records every terminal write (duration, byte size, backpressure signal) and a + * per-frame summary (build time, line count, full-redraw flag, event-loop lag). + * Used to investigate streaming render stutter, especially on Windows where + * ConPTY / Windows Terminal stdout writes are significantly more expensive than + * on Unix pseudoterminals. + */ + +import * as fs from "node:fs"; +import * as os from "node:os"; +import * as path from "node:path"; +import { monitorEventLoopDelay } from "node:perf_hooks"; + +type EventLoopHistogram = ReturnType; + +const FLUSH_RECORD_THRESHOLD = 100; + +function resolveProfilePath(envValue: string): string { + if (envValue === "1" || envValue.toLowerCase() === "true") { + return path.join(os.homedir(), ".pi", "agent", "pi-render-profile.jsonl"); + } + return envValue; +} + +function roundMs(value: number): number { + return Math.round(value * 1000) / 1000; +} + +function nsToMs(ns: number): number { + return Math.round((ns / 1e6) * 1000) / 1000; +} + +export class RenderProfiler { + readonly enabled: boolean; + private readonly filePath: string; + private pending: string[] = []; + private histogram: EventLoopHistogram | undefined; + private closed = false; + + constructor(envValue: string | undefined) { + this.enabled = Boolean(envValue); + if (!this.enabled) { + this.filePath = ""; + return; + } + this.filePath = resolveProfilePath(envValue as string); + try { + fs.mkdirSync(path.dirname(this.filePath), { recursive: true }); + // Start each profiled run with a clean file so sessions do not interleave. + fs.writeFileSync(this.filePath, ""); + } catch { + // Best-effort: if the file cannot be prepared, profiling silently no-ops. + } + try { + const histogram = monitorEventLoopDelay({ resolution: 20 }); + histogram.enable(); + this.histogram = histogram; + } catch { + this.histogram = undefined; + } + } + + /** Record a single stdout write: how long it took, its size, and whether the + * stream signalled backpressure (`write` returned false). */ + recordWrite(durationMs: number, bytes: number, ok: boolean): void { + this.record({ + kind: "write", + ms: roundMs(durationMs), + bytes, + ok, + }); + } + + /** Record a completed render frame with build cost and a since-last-frame + * event-loop lag snapshot. */ + recordFrame(fields: { + fullRedraw: boolean; + lines: number; + height: number; + buildMs: number; + totalMs: number; + }): void { + this.record({ + kind: "frame", + fullRedraw: fields.fullRedraw, + lines: fields.lines, + height: fields.height, + buildMs: roundMs(fields.buildMs), + totalMs: roundMs(fields.totalMs), + el: this.snapshotEventLoop(), + }); + } + + private record(entry: Record): void { + if (!this.enabled || this.closed) return; + this.pending.push(`${JSON.stringify({ t: Date.now(), ...entry })}\n`); + if (this.pending.length >= FLUSH_RECORD_THRESHOLD) { + this.flushAsync(); + } + } + + private snapshotEventLoop(): { meanMs: number; maxMs: number } | undefined { + if (!this.histogram) return undefined; + // `mean` is NaN while the histogram has no samples yet (e.g. the very + // first frame); coerce to 0 so the JSONL stays numeric for parsers. + const mean = this.histogram.mean; + const snapshot = { + meanMs: Number.isFinite(mean) ? nsToMs(mean) : 0, + maxMs: nsToMs(this.histogram.max), + }; + this.histogram.reset(); + return snapshot; + } + + private flushAsync(): void { + if (this.pending.length === 0) return; + const chunk = this.pending.join(""); + this.pending = []; + fs.promises.appendFile(this.filePath, chunk).catch(() => {}); + } + + /** Synchronously flush any buffered records. Safe to call at shutdown. */ + flush(): void { + if (!this.enabled || this.pending.length === 0) return; + try { + fs.appendFileSync(this.filePath, this.pending.join("")); + } catch { + // Ignore flush errors + } + this.pending = []; + } + + close(): void { + if (this.closed) return; + this.closed = true; + this.flush(); + this.histogram?.disable(); + this.histogram = undefined; + } +} + +let singleton: RenderProfiler | undefined; + +export function getRenderProfiler(): RenderProfiler { + if (!singleton) { + singleton = new RenderProfiler(process.env["PI_TUI_RENDER_PROFILE"]); + } + return singleton; +} diff --git a/packages/pi-tui/src/terminal.ts b/packages/pi-tui/src/terminal.ts index 3caba9789b..72ffb5f801 100644 --- a/packages/pi-tui/src/terminal.ts +++ b/packages/pi-tui/src/terminal.ts @@ -1,9 +1,11 @@ import * as fs from "node:fs"; import { createRequire } from "node:module"; import * as path from "node:path"; +import { performance } from "node:perf_hooks"; import { fileURLToPath } from "node:url"; import { setKittyProtocolActive } from "./keys.ts"; import { isNativeModifierPressed } from "./native-modifiers.ts"; +import { getRenderProfiler } from "./render-profiler.ts"; import { StdinBuffer } from "./stdin-buffer.ts"; const cjsRequire = createRequire(import.meta.url); @@ -452,7 +454,12 @@ export class ProcessTerminal implements Terminal { } write(data: string): void { - process.stdout.write(data); + const profiler = getRenderProfiler(); + const start = profiler.enabled ? performance.now() : 0; + const ok = process.stdout.write(data); + if (profiler.enabled) { + profiler.recordWrite(performance.now() - start, Buffer.byteLength(data, "utf8"), ok); + } if (this.writeLogPath) { try { fs.appendFileSync(this.writeLogPath, data, { encoding: "utf8" }); diff --git a/packages/pi-tui/src/tui.ts b/packages/pi-tui/src/tui.ts index c578c7d93e..3a3bd2c370 100644 --- a/packages/pi-tui/src/tui.ts +++ b/packages/pi-tui/src/tui.ts @@ -8,6 +8,7 @@ import * as path from "node:path"; import { performance } from "node:perf_hooks"; import { isKeyRelease, matchesKey } from "./keys.ts"; import type { Terminal } from "./terminal.ts"; +import { getRenderProfiler } from "./render-profiler.ts"; import { isOsc11BackgroundColorResponse, parseOsc11BackgroundColor, @@ -717,6 +718,7 @@ export class TUI extends Container { this.terminal.showCursor(); this.terminal.stop(); + getRenderProfiler().close(); } requestRender(force = false): void { @@ -1263,6 +1265,8 @@ export class TUI extends Container { private doRender(): void { if (this.stopped) return; + const profiler = getRenderProfiler(); + const frameStart = profiler.enabled ? performance.now() : 0; const width = this.terminal.columns; const height = this.terminal.rows; const widthChanged = this.previousWidth !== 0 && this.previousWidth !== width; @@ -1278,6 +1282,7 @@ export class TUI extends Container { }; // Render all components to get new lines + const buildStart = profiler.enabled ? performance.now() : 0; let newLines = this.render(width); // Composite overlays into the rendered lines (before differential compare) @@ -1304,6 +1309,18 @@ export class TUI extends Container { newLines = this.applyLineResets(newLines); + const buildMs = profiler.enabled ? performance.now() - buildStart : 0; + const recordFrame = (fullRedraw: boolean): void => { + if (!profiler.enabled) return; + profiler.recordFrame({ + fullRedraw, + lines: newLines.length, + height, + buildMs, + totalMs: performance.now() - frameStart, + }); + }; + // Helper to clear scrollback and viewport and render all new lines const fullRender = (clear: boolean): void => { this.fullRedrawCount += 1; @@ -1331,6 +1348,7 @@ export class TUI extends Container { } buffer += "\x1b[?2026l"; // End synchronized output this.terminal.write(buffer); + recordFrame(true); this.cursorRow = Math.max(0, newLines.length - 1); this.hardwareCursorRow = this.cursorRow; // Reset max lines when clearing, otherwise track growth @@ -1596,6 +1614,7 @@ export class TUI extends Container { // Write entire buffer at once this.terminal.write(buffer); + recordFrame(false); // Track cursor position for next render // cursorRow tracks end of content (for viewport calculation) diff --git a/packages/pi-tui/test/render-profiler.test.ts b/packages/pi-tui/test/render-profiler.test.ts new file mode 100644 index 0000000000..48c71df9fe --- /dev/null +++ b/packages/pi-tui/test/render-profiler.test.ts @@ -0,0 +1,78 @@ +import assert from "node:assert"; +import * as fs from "node:fs"; +import * as os from "node:os"; +import * as path from "node:path"; +import { afterEach, beforeEach, describe, it } from "node:test"; +import { RenderProfiler } from "../src/render-profiler.ts"; + +describe("RenderProfiler", () => { + let tmpDir: string; + + beforeEach(() => { + tmpDir = fs.mkdtempSync(path.join(os.tmpdir(), "pi-rp-test-")); + }); + + afterEach(() => { + try { + fs.rmSync(tmpDir, { recursive: true, force: true }); + } catch { + // ignore cleanup errors + } + }); + + it("is disabled and writes nothing when env is unset", () => { + const file = path.join(tmpDir, "nope.jsonl"); + const profiler = new RenderProfiler(undefined); + assert.equal(profiler.enabled, false); + profiler.recordWrite(1.2, 100, true); + profiler.recordFrame({ fullRedraw: false, lines: 10, height: 5, buildMs: 0.1, totalMs: 0.2 }); + profiler.close(); + assert.equal(fs.existsSync(file), false); + }); + + it("records writes and frames as JSONL when enabled via a custom path", () => { + const file = path.join(tmpDir, "profile.jsonl"); + const profiler = new RenderProfiler(file); + assert.equal(profiler.enabled, true); + profiler.recordWrite(1.2345, 5678, true); + profiler.recordFrame({ fullRedraw: false, lines: 42, height: 24, buildMs: 0.567, totalMs: 3.1234 }); + profiler.close(); + + const lines = fs.readFileSync(file, "utf8").trim().split("\n"); + assert.equal(lines.length, 2); + + const write = JSON.parse(lines[0]!); + assert.equal(write.kind, "write"); + assert.equal(write.ok, true); + assert.equal(write.bytes, 5678); + // duration is rounded to millisecond precision + assert.equal(write.ms, 1.235); + + const frame = JSON.parse(lines[1]!); + assert.equal(frame.kind, "frame"); + assert.equal(frame.fullRedraw, false); + assert.equal(frame.lines, 42); + assert.equal(frame.height, 24); + assert.equal(frame.buildMs, 0.567); + assert.equal(frame.totalMs, 3.123); + assert.equal(typeof frame.el.meanMs, "number"); + assert.equal(typeof frame.el.maxMs, "number"); + }); + + it("creates the parent directory when it does not exist", () => { + const nested = path.join(tmpDir, "a", "b", "profile.jsonl"); + const profiler = new RenderProfiler(nested); + profiler.recordWrite(0.1, 1, true); + profiler.close(); + assert.equal(fs.existsSync(nested), true); + }); + + it("records backpressure via the write ok flag", () => { + const file = path.join(tmpDir, "bp.jsonl"); + const profiler = new RenderProfiler(file); + profiler.recordWrite(10, 4096, false); + profiler.close(); + const rec = JSON.parse(fs.readFileSync(file, "utf8").trim()); + assert.equal(rec.ok, false); + }); +});