perf(tui): incremental step timing and card render caches for long sessions
Resuming a long session (196k events, 2.2k steps, 1.8k tool cards) took ~12s to render and ~800ms to echo one keystroke: - Every step's timing footer called stepTimingAt, which replayed the whole event log per footer - O(steps x events) on the initial render. - pi-tui re-renders every component each frame and relies on per-component line caches, but ToolCardComponent/ContextCardComponent built throwaway Text/Markdown instances inside render(width), re-wrapping every settled card's output on every keystroke. Replace the per-footer replay with one shared StepTimingTracker per chat mount (single O(events) cursor over the append-only log), and cache card rows by width via CardLineCache, dropped by every state mutator and invalidate(). Measured (tmux 200x50, 196k-event session): resume prompt-ready ~12s -> ~7.6s; per-keystroke echo ~800ms median -> ~11ms.
This commit is contained in:
@@ -132,32 +132,58 @@ function timingTotalsAt(state: TimingState, at?: number): TimingTotals {
|
||||
return totals
|
||||
}
|
||||
|
||||
function stepKey(position: StepPosition): string {
|
||||
return `${position.turn}:${position.step}`
|
||||
}
|
||||
|
||||
interface TrackedStep extends TimingState {
|
||||
/** Set at the step's `step/end`; later same-coordinate events no longer advance the step. */
|
||||
closed: boolean
|
||||
}
|
||||
|
||||
/**
|
||||
* Replay one step's accumulated per-phase timing up to clock `at`.
|
||||
* @param events - Session events to replay.
|
||||
* @param position - Turn/step coordinates of the step.
|
||||
* @param at - Render clock to accumulate the open bucket up to.
|
||||
* @returns The step's per-phase totals.
|
||||
* Incremental per-step timing accumulator shared by every step's timing footer
|
||||
* in one transcript. One forward pass over the append-only session log serves
|
||||
* all steps' totals: each query advances a cursor over the events appended
|
||||
* since the previous query, so a transcript of S steps costs O(events) in
|
||||
* total instead of the O(S × events) of replaying the whole log per footer
|
||||
* ([rationale](../../../../../.agents/notes/implemented/bug-fix/2026-08-03-tui-long-session-render-costs.md)).
|
||||
*
|
||||
* The log must be append-only with stable indices (the session `seq = log
|
||||
* length` contract). Event times are consumed as logged: a backward wall-clock
|
||||
* step clamps each bucket at zero rather than cutting the scan off at the
|
||||
* query clock. The open bucket is accumulated to the query clock at lookup,
|
||||
* never during the scan.
|
||||
*/
|
||||
export function stepTimingAt(
|
||||
events: readonly SessionEvent[],
|
||||
position: StepPosition,
|
||||
at: number,
|
||||
): TimingTotals {
|
||||
const startIndex = events.findIndex(event => event.type === 'step/start' && sameStep(event, position))
|
||||
if (startIndex < 0) return emptyTimingTotals()
|
||||
const start = events[startIndex] as Extract<SessionEvent, { type: 'step/start' }>
|
||||
const state = timingState(start.time)
|
||||
for (let index = startIndex + 1; index < events.length; index += 1) {
|
||||
const event = events[index] as SessionEvent
|
||||
if (event.time > at) break
|
||||
if ((event.type === 'assistant/chunk' || event.type === 'tool/call' || event.type === 'step/end')
|
||||
&& sameStep(event, position)) {
|
||||
advanceStepTiming(state, event)
|
||||
if (event.type === 'step/end') break
|
||||
export class StepTimingTracker {
|
||||
private scanned = 0
|
||||
private readonly steps = new Map<string, TrackedStep>()
|
||||
|
||||
/**
|
||||
* Advance over events appended since the previous query, then return one
|
||||
* step's accumulated per-phase timing up to clock `at`.
|
||||
* @param events - Current session event log (append-only).
|
||||
* @param position - Turn/step coordinates of the queried step.
|
||||
* @param at - Render clock to accumulate the open bucket up to.
|
||||
* @returns The step's per-phase totals; empty when the step never started.
|
||||
*/
|
||||
totalsAt(events: readonly SessionEvent[], position: StepPosition, at: number): TimingTotals {
|
||||
for (; this.scanned < events.length; this.scanned += 1) {
|
||||
const event = events[this.scanned] as SessionEvent
|
||||
if (event.type === 'step/start') {
|
||||
const key = stepKey(event.data)
|
||||
if (!this.steps.has(key)) this.steps.set(key, { ...timingState(event.time), closed: false })
|
||||
} else if (event.type === 'assistant/chunk' || event.type === 'tool/call' || event.type === 'step/end') {
|
||||
const state = this.steps.get(stepKey(event.data))
|
||||
if (state !== undefined && !state.closed) {
|
||||
advanceStepTiming(state, event)
|
||||
if (event.type === 'step/end') state.closed = true
|
||||
}
|
||||
}
|
||||
}
|
||||
const state = this.steps.get(stepKey(position))
|
||||
return state === undefined ? emptyTimingTotals() : timingTotalsAt(state, at)
|
||||
}
|
||||
return timingTotalsAt(state, at)
|
||||
}
|
||||
|
||||
/**
|
||||
@@ -191,7 +217,7 @@ const COMPACTING_GLYPH = '⊙'
|
||||
/**
|
||||
* Derive the currently open step's active timing bucket, or `undefined` when no
|
||||
* step is open. The open step is the last `step/start` with no later matching
|
||||
* `step/end`; its bucket is replayed with the same rules as {@link stepTimingAt}.
|
||||
* `step/end`; its bucket is replayed with the same rules as {@link StepTimingTracker}.
|
||||
* @param events - Session events to scan.
|
||||
* @returns The open step's active bucket, or `undefined`.
|
||||
*/
|
||||
|
||||
@@ -33,8 +33,8 @@ import { contentText, type ParsedArguments } from './content.ts'
|
||||
import {
|
||||
formatCompletionTime,
|
||||
formatTimingTotals,
|
||||
stepTimingAt,
|
||||
type StepPosition,
|
||||
type StepTimingTracker,
|
||||
} from '../chat/timing.ts'
|
||||
|
||||
/** Concatenate the text of every block of one type, separated by blank lines. */
|
||||
@@ -228,6 +228,7 @@ class StepTimingComponent extends Container {
|
||||
constructor(
|
||||
private readonly position: StepPosition,
|
||||
private readonly events: () => readonly SessionEvent[],
|
||||
private readonly tracker: StepTimingTracker,
|
||||
private readonly now: () => number,
|
||||
private readonly palette: Palette,
|
||||
) {
|
||||
@@ -247,7 +248,7 @@ class StepTimingComponent extends Container {
|
||||
|
||||
private rebuild(): void {
|
||||
this.clear()
|
||||
const totals = stepTimingAt(this.events(), this.position, this.completionTime ?? this.now())
|
||||
const totals = this.tracker.totalsAt(this.events(), this.position, this.completionTime ?? this.now())
|
||||
const timing = formatTimingTotals(totals, true)
|
||||
const header = this.completionTime === undefined
|
||||
? timing
|
||||
@@ -277,13 +278,14 @@ export class StreamingAssistantComponent extends Container {
|
||||
/** The step's turn/step coordinates, used to group steps into their turn. */
|
||||
readonly position: StepPosition,
|
||||
events: () => readonly SessionEvent[],
|
||||
tracker: StepTimingTracker,
|
||||
now: () => number,
|
||||
private showReasoning: boolean,
|
||||
private readonly palette: Palette,
|
||||
private readonly mdTheme: MarkdownTheme,
|
||||
) {
|
||||
super()
|
||||
this.timing = new StepTimingComponent(position, events, now, palette)
|
||||
this.timing = new StepTimingComponent(position, events, tracker, now, palette)
|
||||
this.rebuild()
|
||||
}
|
||||
|
||||
@@ -409,8 +411,43 @@ interface CardBody {
|
||||
*/
|
||||
export type ToolCardVisibility = 'hidden' | 'collapsed' | 'expanded'
|
||||
|
||||
/**
|
||||
* Transcript card with a width-keyed rendered-row cache. pi-tui re-renders
|
||||
* every component each frame and relies on per-component line caches (its own
|
||||
* `Text`/`Markdown` do this); a card that rebuilds rows inside `render(width)`
|
||||
* would re-wrap its output every frame
|
||||
* ([rationale](../../../../../.agents/notes/implemented/bug-fix/2026-08-03-tui-long-session-render-costs.md)).
|
||||
* Subclasses render through {@link renderLines} and call {@link dropLines}
|
||||
* from every state mutator; with `invalidate()` (pi-tui's tree-wide cascade)
|
||||
* also dropping, a state change always re-renders.
|
||||
*/
|
||||
abstract class CachedCardComponent implements Component {
|
||||
private cached: { width: number; lines: string[] } | undefined
|
||||
|
||||
/** Discard the cached rows so the next render recomputes them. */
|
||||
protected dropLines(): void {
|
||||
this.cached = undefined
|
||||
}
|
||||
|
||||
invalidate(): void {
|
||||
this.cached = undefined
|
||||
}
|
||||
|
||||
render(width: number): string[] {
|
||||
if (this.cached?.width !== width) this.cached = { width, lines: this.renderLines(width) }
|
||||
return this.cached.lines
|
||||
}
|
||||
|
||||
/**
|
||||
* Render the card's rows for `width` without caching.
|
||||
* @param width - Render width the rows are wrapped to.
|
||||
* @returns The card's rows.
|
||||
*/
|
||||
protected abstract renderLines(width: number): string[]
|
||||
}
|
||||
|
||||
/** A tool call and its result, rendered as a collapsible status card. */
|
||||
export class ToolCardComponent implements Component {
|
||||
export class ToolCardComponent extends CachedCardComponent {
|
||||
private result: { content: ContentBlock[]; isError: boolean; meta?: JsonValue } | undefined
|
||||
private visibility: ToolCardVisibility = 'collapsed'
|
||||
private callView: ToolCallView
|
||||
@@ -426,6 +463,7 @@ export class ToolCardComponent implements Component {
|
||||
private readonly palette: Palette,
|
||||
private readonly mdTheme: MarkdownTheme,
|
||||
) {
|
||||
super()
|
||||
this.callView = this.presentCall()
|
||||
}
|
||||
|
||||
@@ -447,6 +485,7 @@ export class ToolCardComponent implements Component {
|
||||
*/
|
||||
updateResult(event: Extract<SessionEvent, { type: 'tool/result' }>['data']): void {
|
||||
this.diffBodyCache = undefined
|
||||
this.dropLines()
|
||||
const result = event.message.content[0]
|
||||
this.result = {
|
||||
content: [...result.content],
|
||||
@@ -469,11 +508,10 @@ export class ToolCardComponent implements Component {
|
||||
*/
|
||||
setVisibility(visibility: ToolCardVisibility): void {
|
||||
this.visibility = visibility
|
||||
this.dropLines()
|
||||
}
|
||||
|
||||
invalidate(): void {}
|
||||
|
||||
render(width: number): string[] {
|
||||
protected renderLines(width: number): string[] {
|
||||
// Hidden renders nothing — not even the leading gap — so the transcript
|
||||
// keeps only the conversation, the way Codex hides tool calls.
|
||||
if (this.visibility === 'hidden') return []
|
||||
@@ -725,7 +763,7 @@ function stripReminderFrame(text: string): string {
|
||||
* well-formed XML, which made both the fold and the frame-line suppression
|
||||
* content-dependent.
|
||||
*/
|
||||
export class ContextCardComponent implements Component {
|
||||
export class ContextCardComponent extends CachedCardComponent {
|
||||
private expanded = false
|
||||
|
||||
constructor(
|
||||
@@ -733,7 +771,9 @@ export class ContextCardComponent implements Component {
|
||||
private readonly text: string,
|
||||
private readonly maxOutputLines: number,
|
||||
private readonly palette: Palette,
|
||||
) {}
|
||||
) {
|
||||
super()
|
||||
}
|
||||
|
||||
/**
|
||||
* Expand or collapse the card body.
|
||||
@@ -741,11 +781,10 @@ export class ContextCardComponent implements Component {
|
||||
*/
|
||||
setExpanded(expanded: boolean): void {
|
||||
this.expanded = expanded
|
||||
this.dropLines()
|
||||
}
|
||||
|
||||
invalidate(): void {}
|
||||
|
||||
render(width: number): string[] {
|
||||
protected renderLines(width: number): string[] {
|
||||
const header = this.palette.dim(`Context · ${displayText(this.label)}`)
|
||||
// Emptiness is decided on the stripped text: styling a blank body would yield
|
||||
// one escape-only row, which reads as a stray blank line under the header.
|
||||
|
||||
@@ -88,6 +88,7 @@ import {
|
||||
runningPhaseGlyph,
|
||||
STATUS_ANIMATION_INTERVAL_MS,
|
||||
STATUS_FADE_MS,
|
||||
StepTimingTracker,
|
||||
TIMING_BUCKET_GLYPHS,
|
||||
type StepPosition,
|
||||
} from './chat/timing.ts'
|
||||
@@ -358,6 +359,9 @@ export function createTuiChat(
|
||||
let toolsVisibility: ToolCardVisibility = 'collapsed'
|
||||
let streaming: StreamingAssistantComponent | undefined
|
||||
let completedStreaming: StreamingAssistantComponent | undefined
|
||||
// One shared accumulator serves every step's timing footer; per-footer
|
||||
// replay of the whole log is quadratic on a long resumed session.
|
||||
const stepTimingTracker = new StepTimingTracker()
|
||||
// Assistant step components in model order per turn, for hidden-mode folding:
|
||||
// with tool cards hidden, a turn keeps one Assistant header and later steps
|
||||
// render as headerless continuations (see applyTurnFolding).
|
||||
@@ -769,6 +773,7 @@ export function createTuiChat(
|
||||
streaming = new StreamingAssistantComponent(
|
||||
position,
|
||||
() => agent.session.events,
|
||||
stepTimingTracker,
|
||||
now,
|
||||
showReasoning,
|
||||
palette,
|
||||
|
||||
90
packages/ui/tui/tests/timing-tracker.spec.ts
Normal file
90
packages/ui/tui/tests/timing-tracker.spec.ts
Normal file
@@ -0,0 +1,90 @@
|
||||
import { describe, expect, it } from 'vitest'
|
||||
import type { SessionEvent } from '@deepseek-ai/dsh-session'
|
||||
import { StepTimingTracker } from '../src/chat/timing.ts'
|
||||
|
||||
/** One completed two-phase step plus a tool call, in event-log order. */
|
||||
function stepEvents(turn: number, step: number, base: number, seq: number): SessionEvent[] {
|
||||
return [
|
||||
{ type: 'step/start', seq: seq, time: base, data: { turn, step } },
|
||||
{ type: 'assistant/chunk', seq: seq + 1, time: base + 100, data: { turn, step, chunk: { type: 'block-start', index: 0, blockType: 'reasoning' } } },
|
||||
{ type: 'assistant/chunk', seq: seq + 2, time: base + 300, data: { turn, step, chunk: { type: 'text-delta', index: 1, text: 'hi' } } },
|
||||
{ type: 'tool/call', seq: seq + 3, time: base + 450, data: { turn, step, callId: 'call-1', name: 'bash', arguments: '{}' } },
|
||||
{ type: 'step/end', seq: seq + 4, time: base + 700, data: { turn, step } },
|
||||
] as SessionEvent[]
|
||||
}
|
||||
|
||||
describe('StepTimingTracker', () => {
|
||||
it('accumulates each phase from the step lifecycle', () => {
|
||||
const tracker = new StepTimingTracker()
|
||||
const events = stepEvents(1, 1, 1_000, 0)
|
||||
expect(tracker.totalsAt(events, { turn: 1, step: 1 }, 2_000)).toEqual({
|
||||
ttft: 100, // step/start -> first chunk
|
||||
thinking: 200, // reasoning block-start -> text delta
|
||||
responding: 150, // text delta -> tool call
|
||||
tools: 250, // tool call -> step/end
|
||||
})
|
||||
})
|
||||
|
||||
it('returns empty totals for a step that never started', () => {
|
||||
const tracker = new StepTimingTracker()
|
||||
expect(tracker.totalsAt(stepEvents(1, 1, 1_000, 0), { turn: 9, step: 9 }, 2_000)).toEqual({
|
||||
ttft: 0, thinking: 0, responding: 0, tools: 0,
|
||||
})
|
||||
})
|
||||
|
||||
it('accumulates the open bucket to the query clock without mutating tracked state', () => {
|
||||
const tracker = new StepTimingTracker()
|
||||
const events = [
|
||||
{ type: 'step/start', seq: 0, time: 1_000, data: { turn: 1, step: 1 } },
|
||||
] as SessionEvent[]
|
||||
expect(tracker.totalsAt(events, { turn: 1, step: 1 }, 1_250).ttft).toBe(250)
|
||||
expect(tracker.totalsAt(events, { turn: 1, step: 1 }, 1_400).ttft).toBe(400)
|
||||
})
|
||||
|
||||
it('matches a fresh replay when queried incrementally across appends', () => {
|
||||
const incremental = new StepTimingTracker()
|
||||
const first = stepEvents(1, 1, 1_000, 0)
|
||||
incremental.totalsAt(first, { turn: 1, step: 1 }, 5_000)
|
||||
const events = [...first, ...stepEvents(1, 2, 3_000, first.length)]
|
||||
const fresh = new StepTimingTracker()
|
||||
for (const position of [{ turn: 1, step: 1 }, { turn: 1, step: 2 }]) {
|
||||
expect(incremental.totalsAt(events, position, 5_000)).toEqual(fresh.totalsAt(events, position, 5_000))
|
||||
}
|
||||
})
|
||||
|
||||
it('serves interleaved steps from one shared scan', () => {
|
||||
const tracker = new StepTimingTracker()
|
||||
const events = [
|
||||
{ type: 'step/start', seq: 0, time: 1_000, data: { turn: 1, step: 1 } },
|
||||
{ type: 'step/start', seq: 1, time: 1_100, data: { turn: 1, step: 2 } },
|
||||
{ type: 'assistant/chunk', seq: 2, time: 1_200, data: { turn: 1, step: 2, chunk: { type: 'text-delta', index: 0, text: 'x' } } },
|
||||
{ type: 'step/end', seq: 3, time: 1_500, data: { turn: 1, step: 2 } },
|
||||
{ type: 'step/end', seq: 4, time: 1_600, data: { turn: 1, step: 1 } },
|
||||
] as SessionEvent[]
|
||||
expect(tracker.totalsAt(events, { turn: 1, step: 1 }, 9_000)).toEqual({ ttft: 600, thinking: 0, responding: 0, tools: 0 })
|
||||
expect(tracker.totalsAt(events, { turn: 1, step: 2 }, 9_000)).toEqual({ ttft: 100, thinking: 0, responding: 300, tools: 0 })
|
||||
})
|
||||
|
||||
it('keeps the first step/start when a duplicate arrives while the step is open', () => {
|
||||
const tracker = new StepTimingTracker()
|
||||
const events = [
|
||||
{ type: 'step/start', seq: 0, time: 1_000, data: { turn: 1, step: 1 } },
|
||||
{ type: 'step/start', seq: 1, time: 1_500, data: { turn: 1, step: 1 } },
|
||||
] as SessionEvent[]
|
||||
expect(tracker.totalsAt(events, { turn: 1, step: 1 }, 2_000).ttft).toBe(1_000)
|
||||
})
|
||||
|
||||
it('ignores same-coordinate events after the step closed', () => {
|
||||
const tracker = new StepTimingTracker()
|
||||
const events = [
|
||||
...stepEvents(1, 1, 1_000, 0),
|
||||
// A stray duplicate start and a late chunk reuse the coordinates; the
|
||||
// closed step's totals stay pinned.
|
||||
{ type: 'step/start', seq: 5, time: 9_000, data: { turn: 1, step: 1 } },
|
||||
{ type: 'assistant/chunk', seq: 6, time: 9_100, data: { turn: 1, step: 1, chunk: { type: 'text-delta', index: 0, text: 'late' } } },
|
||||
] as SessionEvent[]
|
||||
expect(tracker.totalsAt(events, { turn: 1, step: 1 }, 10_000)).toEqual({
|
||||
ttft: 100, thinking: 200, responding: 150, tools: 250,
|
||||
})
|
||||
})
|
||||
})
|
||||
74
packages/ui/tui/tests/transcript-card-cache.spec.ts
Normal file
74
packages/ui/tui/tests/transcript-card-cache.spec.ts
Normal file
@@ -0,0 +1,74 @@
|
||||
import { describe, expect, it } from 'vitest'
|
||||
import type { SessionEvent } from '@deepseek-ai/dsh-session'
|
||||
import { createToolResultMessage, CallId } from '@deepseek-ai/dsh-llm'
|
||||
import { ContextCardComponent, ToolCardComponent } from '../src/components/transcript.ts'
|
||||
import { parseArguments } from '../src/components/content.ts'
|
||||
import { createPalette, markdownTheme } from '../src/components/theme.ts'
|
||||
|
||||
const palette = createPalette(false)
|
||||
const mdTheme = markdownTheme(palette)
|
||||
|
||||
function toolCard(): ToolCardComponent {
|
||||
return new ToolCardComponent('bash', parseArguments('{"command":"ls"}'), undefined, 10, 2_000, palette, mdTheme)
|
||||
}
|
||||
|
||||
function toolResult(text: string): Extract<SessionEvent, { type: 'tool/result' }>['data'] {
|
||||
const message = createToolResultMessage({
|
||||
callId: CallId('call-1'),
|
||||
content: [{ type: 'text', text }],
|
||||
isError: false,
|
||||
})
|
||||
return { turn: 1, step: 1, message }
|
||||
}
|
||||
|
||||
// pi-tui re-renders every component each frame; the cards must serve repeat
|
||||
// same-width renders from their line cache and drop it on every state change.
|
||||
describe('transcript card render caches', () => {
|
||||
it('tool card: repeat same-width renders return the cached rows', () => {
|
||||
const card = toolCard()
|
||||
const first = card.render(80)
|
||||
expect(card.render(80)).toBe(first)
|
||||
const narrower = card.render(60)
|
||||
expect(narrower).not.toBe(first)
|
||||
expect(card.render(60)).toBe(narrower)
|
||||
})
|
||||
|
||||
it('tool card: result, visibility, and invalidate() each drop the cache', () => {
|
||||
const card = toolCard()
|
||||
const pending = card.render(80)
|
||||
card.updateResult(toolResult('output line'))
|
||||
const settled = card.render(80)
|
||||
expect(settled).not.toBe(pending)
|
||||
expect(settled.join('\n')).toContain('●')
|
||||
|
||||
card.setVisibility('hidden')
|
||||
expect(card.render(80)).toEqual([])
|
||||
|
||||
card.setVisibility('collapsed')
|
||||
const restored = card.render(80)
|
||||
expect(restored).toEqual(settled)
|
||||
expect(restored).not.toBe(settled)
|
||||
|
||||
card.invalidate()
|
||||
expect(card.render(80)).not.toBe(restored)
|
||||
})
|
||||
|
||||
it('context card: caches by width and drops on setExpanded and invalidate()', () => {
|
||||
const card = new ContextCardComponent('workspace-context', 'line one\nline two', 10, palette)
|
||||
const first = card.render(80)
|
||||
expect(card.render(80)).toBe(first)
|
||||
|
||||
// Same width across the mutation, so a hit here would prove a kept cache.
|
||||
card.setExpanded(true)
|
||||
const expanded = card.render(80)
|
||||
expect(expanded).not.toBe(first)
|
||||
expect(card.render(80)).toBe(expanded)
|
||||
|
||||
card.invalidate()
|
||||
const reRendered = card.render(80)
|
||||
expect(reRendered).not.toBe(expanded)
|
||||
expect(reRendered).toEqual(expanded)
|
||||
|
||||
expect(card.render(60)).not.toBe(reRendered)
|
||||
})
|
||||
})
|
||||
Reference in New Issue
Block a user