diff --git a/src/ink/ink.tsx b/src/ink/ink.tsx index de7c02df1..d3c8dc41e 100644 --- a/src/ink/ink.tsx +++ b/src/ink/ink.tsx @@ -1114,7 +1114,9 @@ export default class Ink { offsetY: -elTop, prevScreen: undefined }); - const rendered = output.get(); + const rendered = output.get({ + suppressHighWriteRatioDiagnostics: true + }); // renderNodeToOutput wrote our offset positions to nodeCache — // corrupts the main render (it'd blit from wrong coords). Mark the // subtree dirty so the next main render repaints + re-caches diff --git a/src/ink/output.test.ts b/src/ink/output.test.ts new file mode 100644 index 000000000..ad4a397b1 --- /dev/null +++ b/src/ink/output.test.ts @@ -0,0 +1,258 @@ +import { afterEach, beforeEach, expect, spyOn, test } from 'bun:test' + +import * as debug from '../utils/debug.ts' +import Output from './output.ts' +import { + CharPool, + createScreen, + HyperlinkPool, + StylePool, + type Screen, +} from './screen.ts' + +let logSpy: ReturnType + +type Harness = { + output: Output + stylePool: StylePool + charPool: CharPool + hyperlinkPool: HyperlinkPool +} + +function createHarness(width: number, height: number): Harness { + const stylePool = new StylePool() + const charPool = new CharPool() + const hyperlinkPool = new HyperlinkPool() + const screen = createScreen(width, height, stylePool, charPool, hyperlinkPool) + + return { + output: new Output({ width, height, stylePool, screen }), + stylePool, + charPool, + hyperlinkPool, + } +} + +function resetOutput(harness: Harness, width: number, height: number): void { + harness.output.reset( + width, + height, + createScreen( + width, + height, + harness.stylePool, + harness.charPool, + harness.hyperlinkPool, + ), + ) +} + +function createScreenForHarness( + harness: Harness, + width: number, + height: number, +): Screen { + return createScreen( + width, + height, + harness.stylePool, + harness.charPool, + harness.hyperlinkPool, + ) +} + +function writeFullFrame(output: Output, width: number, height: number): void { + const row = 'x'.repeat(width) + + for (let y = 0; y < height; y++) { + output.write(0, y, row) + } +} + +beforeEach(() => { + logSpy = spyOn(debug, 'logForDebugging').mockImplementation(() => {}) +}) + +afterEach(() => { + logSpy.mockRestore() +}) + +test('classifies first render high-write frames as expected full redraws', () => { + const harness = createHarness(80, 20) + + writeFullFrame(harness.output, 80, 20) + harness.output.get({ highWriteRatioReason: 'first-render' }) + + expect(logSpy).toHaveBeenCalledTimes(1) + expect(logSpy.mock.calls[0]?.[0]).toContain('render.high_write_ratio') + expect(logSpy.mock.calls[0]?.[0]).toContain('reason=first-render') + expect(logSpy.mock.calls[0]?.[0]).toContain('expected=true') + expect(logSpy.mock.calls[0]?.[1]).toEqual({ level: 'debug' }) +}) + +test('classifies resize high-write frames as expected full redraws', () => { + const harness = createHarness(100, 14) + + writeFullFrame(harness.output, 100, 14) + harness.output.get({ highWriteRatioReason: 'resize' }) + + expect(logSpy).toHaveBeenCalledTimes(1) + expect(logSpy.mock.calls[0]?.[0]).toContain('reason=resize') + expect(logSpy.mock.calls[0]?.[0]).toContain('expected=true') + expect(logSpy.mock.calls[0]?.[1]).toEqual({ level: 'debug' }) +}) + +test('aggregates sustained unknown high-write frames instead of logging every frame', () => { + const harness = createHarness(80, 20) + + for (let frame = 0; frame < 5; frame++) { + if (frame > 0) { + resetOutput(harness, 80, 20) + } + writeFullFrame(harness.output, 80, 20) + harness.output.get() + } + + expect(logSpy).toHaveBeenCalledTimes(1) + expect(logSpy.mock.calls[0]?.[0]).toContain('reason=unknown') + expect(logSpy.mock.calls[0]?.[0]).toContain('frames=3') + expect(logSpy.mock.calls[0]?.[1]).toEqual({ level: 'warn' }) +}) + +test('suppresses high-write diagnostics and resets unknown aggregation state', () => { + const harness = createHarness(80, 20) + + for (let frame = 0; frame < 2; frame++) { + if (frame > 0) { + resetOutput(harness, 80, 20) + } + writeFullFrame(harness.output, 80, 20) + harness.output.get() + } + + for (let frame = 0; frame < 5; frame++) { + resetOutput(harness, 80, 20) + writeFullFrame(harness.output, 80, 20) + harness.output.get({ suppressHighWriteRatioDiagnostics: true }) + } + + expect(logSpy).not.toHaveBeenCalled() + + for (let frame = 0; frame < 2; frame++) { + resetOutput(harness, 80, 20) + writeFullFrame(harness.output, 80, 20) + harness.output.get() + } + + expect(logSpy).not.toHaveBeenCalled() + + resetOutput(harness, 80, 20) + writeFullFrame(harness.output, 80, 20) + harness.output.get() + + expect(logSpy).toHaveBeenCalledTimes(1) + expect(logSpy.mock.calls[0]?.[0]).toContain('reason=unknown') + expect(logSpy.mock.calls[0]?.[0]).toContain('frames=3') + expect(logSpy.mock.calls[0]?.[1]).toEqual({ level: 'warn' }) +}) + +test('dimension changes reset sustained unknown high-write aggregation', () => { + const harness = createHarness(80, 20) + + for (let frame = 0; frame < 2; frame++) { + if (frame > 0) { + resetOutput(harness, 80, 20) + } + writeFullFrame(harness.output, 80, 20) + harness.output.get() + } + + resetOutput(harness, 81, 20) + writeFullFrame(harness.output, 81, 20) + harness.output.get() + + expect(logSpy).not.toHaveBeenCalled() + + for (let frame = 0; frame < 2; frame++) { + resetOutput(harness, 81, 20) + writeFullFrame(harness.output, 81, 20) + harness.output.get() + } + + expect(logSpy).toHaveBeenCalledTimes(1) + expect(logSpy.mock.calls[0]?.[0]).toContain('frames=3') +}) + +test('flags suspicious terminal columns only once', () => { + const harness = createHarness(1201, 1) + + writeFullFrame(harness.output, 1201, 1) + harness.output.get() + + resetOutput(harness, 1201, 1) + writeFullFrame(harness.output, 1201, 1) + harness.output.get() + + expect(logSpy).toHaveBeenCalledTimes(1) + expect(logSpy.mock.calls[0]?.[0]).toContain( + 'reason=suspicious-terminal-columns', + ) + expect(logSpy.mock.calls[0]?.[1]).toEqual({ level: 'warn' }) +}) + +test('continues sustained unknown aggregation at suspicious terminal widths', () => { + const harness = createHarness(1201, 1) + + for (let frame = 0; frame < 3; frame++) { + if (frame > 0) { + resetOutput(harness, 1201, 1) + } + writeFullFrame(harness.output, 1201, 1) + harness.output.get() + } + + expect(logSpy).toHaveBeenCalledTimes(2) + expect(logSpy.mock.calls[0]?.[0]).toContain( + 'reason=suspicious-terminal-columns', + ) + expect(logSpy.mock.calls[0]?.[0]).toContain('frames=1') + expect(logSpy.mock.calls[0]?.[1]).toEqual({ level: 'warn' }) + expect(logSpy.mock.calls[1]?.[0]).toContain('reason=unknown') + expect(logSpy.mock.calls[1]?.[0]).toContain('frames=3') + expect(logSpy.mock.calls[1]?.[1]).toEqual({ level: 'warn' }) +}) + +test('suspicious terminal columns can be flagged again after returning to normal width', () => { + const harness = createHarness(1201, 1) + + writeFullFrame(harness.output, 1201, 1) + harness.output.get() + + resetOutput(harness, 80, 20) + writeFullFrame(harness.output, 80, 20) + harness.output.get({ highWriteRatioReason: 'resize' }) + + resetOutput(harness, 1201, 1) + writeFullFrame(harness.output, 1201, 1) + harness.output.get() + + expect(logSpy).toHaveBeenCalledTimes(3) + expect(logSpy.mock.calls[0]?.[0]).toContain( + 'reason=suspicious-terminal-columns', + ) + expect(logSpy.mock.calls[1]?.[0]).toContain('reason=resize') + expect(logSpy.mock.calls[2]?.[0]).toContain( + 'reason=suspicious-terminal-columns', + ) +}) + +test('does not report high-write diagnostics for blit-heavy incremental frames', () => { + const harness = createHarness(80, 20) + const prevScreen = createScreenForHarness(harness, 80, 20) + + harness.output.blit(prevScreen, 0, 0, 80, 20) + harness.output.write(0, 0, 'changed') + harness.output.get() + + expect(logSpy).not.toHaveBeenCalled() +}) diff --git a/src/ink/output.ts b/src/ink/output.ts index 16b5ae27f..21d2bbf37 100644 --- a/src/ink/output.ts +++ b/src/ink/output.ts @@ -59,6 +59,38 @@ type Options = { screen: Screen } +export type HighWriteRatioReason = + | 'first-render' + | 'resize' + | 'remount' + | 'debug-full-redraw' + | 'suspicious-terminal-columns' + | 'unknown' + +export type GetOptions = { + highWriteRatioReason?: HighWriteRatioReason + suppressHighWriteRatioDiagnostics?: boolean +} + +type HighWriteRatioStats = { + blitCells: number + writeCells: number + screenHeight: number + screenWidth: number +} + +const HIGH_WRITE_RATIO_MIN_CELLS = 1000 +const HIGH_WRITE_RATIO_STREAK_THRESHOLD = 3 +const HIGH_WRITE_RATIO_REPEAT_INTERVAL = 20 +const SUSPICIOUS_TERMINAL_COLUMNS = 1000 + +const EXPECTED_HIGH_WRITE_REASONS = new Set([ + 'first-render', + 'resize', + 'remount', + 'debug-full-redraw', +]) + export type Operation = | WriteOperation | ClipOperation @@ -176,6 +208,9 @@ export default class Output { private readonly operations: Operation[] = [] private charCache: Map = new Map() + private highWriteRatioStreak = 0 + private highWriteRatioStreakReason: HighWriteRatioReason = 'unknown' + private suspiciousColumnsLogged = false constructor(options: Options) { const { width, height, stylePool, screen } = options @@ -196,12 +231,19 @@ export default class Output { * becomes a cache hit. */ reset(width: number, height: number, screen: Screen): void { + const dimensionsChanged = width !== this.width || height !== this.height this.width = width this.height = height this.screen = screen this.operations.length = 0 resetScreen(screen, width, height) if (this.charCache.size > 16384) this.charCache.clear() + if (dimensionsChanged) { + this.resetHighWriteRatioStreak() + if (width <= SUSPICIOUS_TERMINAL_COLUMNS) { + this.suspiciousColumnsLogged = false + } + } } /** @@ -265,7 +307,7 @@ export default class Output { }) } - get(): Screen { + get(options: GetOptions = {}): Screen { const screen = this.screen const screenWidth = this.width const screenHeight = this.height @@ -519,16 +561,107 @@ export default class Output { } } - // Log blit/write ratio for debugging - high write count suggests blitting isn't working - const totalCells = blitCells + writeCells - if (totalCells > 1000 && writeCells > blitCells) { - logForDebugging( - `High write ratio: blit=${blitCells}, write=${writeCells} (${((writeCells / totalCells) * 100).toFixed(1)}% writes), screen=${screenHeight}x${screenWidth}`, - ) - } + this.maybeLogHighWriteRatio( + { blitCells, writeCells, screenHeight, screenWidth }, + options, + ) return screen } + + private maybeLogHighWriteRatio( + stats: HighWriteRatioStats, + options: GetOptions, + ): void { + if (options.suppressHighWriteRatioDiagnostics) { + this.resetHighWriteRatioStreak() + return + } + + const { blitCells, writeCells, screenWidth } = stats + const totalCells = blitCells + writeCells + if ( + totalCells <= HIGH_WRITE_RATIO_MIN_CELLS || + writeCells <= blitCells + ) { + this.resetHighWriteRatioStreak() + return + } + + if (screenWidth > SUSPICIOUS_TERMINAL_COLUMNS) { + if (!this.suspiciousColumnsLogged) { + this.logHighWriteRatio(stats, { + reason: 'suspicious-terminal-columns', + expected: false, + frames: 1, + level: 'warn', + }) + this.suspiciousColumnsLogged = true + } + } + + const reason = options.highWriteRatioReason ?? 'unknown' + if (EXPECTED_HIGH_WRITE_REASONS.has(reason)) { + this.logHighWriteRatio(stats, { + reason, + expected: true, + frames: 1, + level: 'debug', + }) + this.resetHighWriteRatioStreak() + return + } + + if (this.highWriteRatioStreakReason !== reason) { + this.highWriteRatioStreakReason = reason + this.highWriteRatioStreak = 0 + } + + this.highWriteRatioStreak++ + if ( + this.highWriteRatioStreak === HIGH_WRITE_RATIO_STREAK_THRESHOLD || + (this.highWriteRatioStreak > HIGH_WRITE_RATIO_STREAK_THRESHOLD && + (this.highWriteRatioStreak - HIGH_WRITE_RATIO_STREAK_THRESHOLD) % + HIGH_WRITE_RATIO_REPEAT_INTERVAL === + 0) + ) { + this.logHighWriteRatio(stats, { + reason, + expected: false, + frames: this.highWriteRatioStreak, + level: 'warn', + }) + } + } + + private resetHighWriteRatioStreak(): void { + this.highWriteRatioStreak = 0 + this.highWriteRatioStreakReason = 'unknown' + } + + private logHighWriteRatio( + stats: HighWriteRatioStats, + { + reason, + expected, + frames, + level, + }: { + reason: HighWriteRatioReason + expected: boolean + frames: number + level: 'debug' | 'warn' + }, + ): void { + const { blitCells, writeCells, screenHeight, screenWidth } = stats + const totalCells = blitCells + writeCells + logForDebugging( + `render.high_write_ratio: reason=${reason} expected=${expected} frames=${frames} ` + + `blit=${blitCells} write=${writeCells} ratio=${((writeCells / totalCells) * 100).toFixed(1)}% ` + + `screen=${screenHeight}x${screenWidth}`, + { level }, + ) + } } function stylesEqual(a: AnsiCode[], b: AnsiCode[]): boolean { diff --git a/src/ink/render-to-screen.ts b/src/ink/render-to-screen.ts index 0992dc946..d9c108f63 100644 --- a/src/ink/render-to-screen.ts +++ b/src/ink/render-to-screen.ts @@ -110,7 +110,7 @@ export function renderToScreen( // renderNodeToOutput queues writes into Output; .get() flushes the // queue into the Screen's cell arrays. Without this the screen is // blank (constructor-zero). - const rendered = output.get() + const rendered = output.get({ suppressHighWriteRatioDiagnostics: true }) const t3 = performance.now() // Unmount so next call gets a fresh tree. Leaves root/container/pools. diff --git a/src/ink/renderer.test.ts b/src/ink/renderer.test.ts new file mode 100644 index 000000000..8afc4b13a --- /dev/null +++ b/src/ink/renderer.test.ts @@ -0,0 +1,151 @@ +import { expect, test } from 'bun:test' + +import { emptyFrame, type Frame } from './frame.ts' +import { classifyHighWriteRatioReason } from './renderer.ts' +import { + CharPool, + createScreen, + HyperlinkPool, + StylePool, +} from './screen.ts' + +const stylePool = new StylePool() +const charPool = new CharPool() +const hyperlinkPool = new HyperlinkPool() + +function createFrame({ + screenWidth, + screenHeight, + viewportWidth = screenWidth, + viewportHeight = screenHeight, +}: { + screenWidth: number + screenHeight: number + viewportWidth?: number + viewportHeight?: number +}): Frame { + return { + screen: createScreen( + screenWidth, + screenHeight, + stylePool, + charPool, + hyperlinkPool, + ), + viewport: { + width: viewportWidth, + height: viewportHeight, + }, + cursor: { x: 0, y: 0, visible: true }, + } +} + +test('high-write classifier identifies initial empty frame as first render', () => { + const frontFrame = emptyFrame(24, 80, stylePool, charPool, hyperlinkPool) + + expect( + classifyHighWriteRatioReason( + { + frontFrame, + backFrame: frontFrame, + isTTY: true, + terminalWidth: 80, + terminalRows: 24, + altScreen: false, + prevFrameContaminated: false, + }, + false, + ), + ).toBe('first-render') +}) + +test('high-write classifier reports debug full redraw when a contaminated empty frame forces repaint', () => { + const frontFrame = emptyFrame(24, 80, stylePool, charPool, hyperlinkPool) + + expect( + classifyHighWriteRatioReason( + { + frontFrame, + backFrame: frontFrame, + isTTY: true, + terminalWidth: 80, + terminalRows: 24, + altScreen: false, + prevFrameContaminated: true, + }, + false, + ), + ).toBe('debug-full-redraw') +}) + +test('high-write classifier does not treat steady alt-screen viewport offset as resize', () => { + const frontFrame = createFrame({ + screenWidth: 120, + screenHeight: 24, + viewportWidth: 120, + viewportHeight: 25, + }) + + expect( + classifyHighWriteRatioReason( + { + frontFrame, + backFrame: frontFrame, + isTTY: true, + terminalWidth: 120, + terminalRows: 24, + altScreen: true, + prevFrameContaminated: true, + }, + false, + ), + ).toBe('remount') +}) + +test('high-write classifier keeps real resize reason ahead of contamination', () => { + const frontFrame = createFrame({ + screenWidth: 120, + screenHeight: 24, + viewportWidth: 120, + viewportHeight: 24, + }) + + expect( + classifyHighWriteRatioReason( + { + frontFrame, + backFrame: frontFrame, + isTTY: true, + terminalWidth: 120, + terminalRows: 24, + altScreen: true, + prevFrameContaminated: true, + }, + false, + ), + ).toBe('resize') +}) + +test('high-write classifier reports absolute removals as remount redraws', () => { + const frontFrame = createFrame({ + screenWidth: 80, + screenHeight: 24, + viewportWidth: 80, + viewportHeight: 24, + }) + + expect( + classifyHighWriteRatioReason( + { + frontFrame, + backFrame: frontFrame, + isTTY: true, + terminalWidth: 80, + terminalRows: 24, + altScreen: false, + prevFrameContaminated: false, + }, + true, + ), + ).toBe('remount') +}) diff --git a/src/ink/renderer.ts b/src/ink/renderer.ts index d87fb3db9..d8c6297f4 100644 --- a/src/ink/renderer.ts +++ b/src/ink/renderer.ts @@ -2,7 +2,7 @@ import { logForDebugging } from 'src/utils/debug.js' import { type DOMElement, markDirty } from './dom.js' import type { Frame } from './frame.js' import { consumeAbsoluteRemovedFlag } from './node-cache.js' -import Output from './output.js' +import Output, { type HighWriteRatioReason } from './output.js' import renderNodeToOutput, { getScrollDrainNode, getScrollHint, @@ -127,6 +127,10 @@ export default function createRenderer( // node's pixels. hasRemovedChild only shields direct siblings. // Normal-flow removals don't paint cross-subtree and are fine. const absoluteRemoved = consumeAbsoluteRemovedFlag() + const highWriteRatioReason = classifyHighWriteRatioReason( + options, + absoluteRemoved, + ) renderNodeToOutput(node, output, { prevScreen: absoluteRemoved || options.prevFrameContaminated @@ -134,7 +138,7 @@ export default function createRenderer( : prevScreen, }) - const renderedScreen = output.get() + const renderedScreen = output.get({ highWriteRatioReason }) // Drain continuation: render cleared scrollbox.dirty, so next frame's // root blit would skip the subtree. markDirty walks ancestors so the @@ -176,3 +180,40 @@ export default function createRenderer( } } } + +export function classifyHighWriteRatioReason( + options: RenderOptions, + absoluteRemoved: boolean, +): HighWriteRatioReason { + const expectedViewportHeight = options.altScreen + ? options.terminalRows + 1 + : options.terminalRows + + if ( + options.frontFrame.viewport.width !== options.terminalWidth || + options.frontFrame.viewport.height !== expectedViewportHeight + ) { + return 'resize' + } + + if ( + options.prevFrameContaminated && + options.frontFrame.screen.width === 0 && + options.frontFrame.screen.height === 0 + ) { + return 'debug-full-redraw' + } + + if (options.prevFrameContaminated || absoluteRemoved) { + return 'remount' + } + + if ( + options.frontFrame.screen.width === 0 && + options.frontFrame.screen.height === 0 + ) { + return 'first-render' + } + + return 'unknown' +}