Render profiler for the TUI

This commit is contained in:
cte 2026-01-09 10:12:40 -08:00
parent 1c61e7f0c5
commit 1b6e0434ab
15 changed files with 1487 additions and 5 deletions

View file

@ -9,6 +9,9 @@ import { setLogger } from "@roo-code/vscode-shim"
import { FlagOptions, isSupportedProvider, OnboardingProviderChoice, supportedProviders } from "../../types/types.js"
import { ASCII_ROO, DEFAULT_FLAGS, REASONING_EFFORTS, SDK_BASE_URL } from "../../types/constants.js"
import { RenderProfiler, getRenderLogPath } from "../../ui/utils/renderProfiler.js"
import { startFrameTracking } from "../../ui/utils/frameTiming.js"
import { wrapStoreWithProfiler } from "../../ui/utils/storeProfiler.js"
import { ExtensionHost, ExtensionHostOptions } from "../../extension-host/index.js"
@ -112,6 +115,22 @@ export async function run(workspaceArg: string, options: FlagOptions) {
console.log("[CLI] TUI disabled (no TTY support), falling back to plain text mode")
}
// Initialize render profiler if enabled via flag or environment variable
const profileRenders = options.profileRenders || process.env.ROO_PROFILE_RENDERS === "1"
if (profileRenders && useTui) {
RenderProfiler.getInstance().configure({ enabled: true })
startFrameTracking() // Start event loop timing measurements
// Wrap Zustand stores with profiler (must be done before App renders)
// Dynamic import to avoid loading stores unless profiling is enabled
const { useCLIStore } = await import("../../ui/store.js")
const { useUIStateStore } = await import("../../ui/stores/uiStateStore.js")
wrapStoreWithProfiler(useCLIStore, "CLIStore")
wrapStoreWithProfiler(useUIStateStore, "UIStateStore")
console.log(`[CLI] Render profiling enabled. Writing to: ${getRenderLogPath()}`)
}
if (!useTui && !options.prompt) {
console.error("[CLI] Error: prompt is required in plain text mode")
console.error("[CLI] Usage: roo [workspace] -P <prompt> [options]")

View file

@ -170,6 +170,16 @@ export class MessageProcessor {
return
}
// Debug: log all message types in this state update
const lastMsg = clineMessages[clineMessages.length - 1]
console.error("[DEBUG MessageProcessor] handleStateMessage", {
msgCount: clineMessages.length,
lastMsgType: lastMsg?.type,
lastMsgAsk: lastMsg?.ask,
lastMsgSay: lastMsg?.say,
partial: lastMsg?.partial,
})
// Get previous state for comparison
const previousState = this.store.getAgentState()
@ -202,6 +212,15 @@ export class MessageProcessor {
})
}
// Debug: log state transition
console.error("[DEBUG MessageProcessor] state transition", {
prevState: previousState.state,
currState: currentState.state,
prevAsk: previousState.currentAsk,
currAsk: currentState.currentAsk,
isWaitingForInput: currentState.isWaitingForInput,
})
// Emit events based on state changes
this.emitStateChangeEvents(previousState, currentState)
@ -329,11 +348,10 @@ export class MessageProcessor {
// Task completed
if (taskCompleted(previousState, currentState)) {
if (this.options.debug) {
debugLog("[MessageProcessor] EMIT taskCompleted", {
success: currentState.currentAsk === "completion_result",
})
}
console.error("[DEBUG MessageProcessor] EMIT taskCompleted", {
success: currentState.currentAsk === "completion_result",
currentAsk: currentState.currentAsk,
})
const completedEvent: TaskCompletedEvent = {
success: currentState.currentAsk === "completion_result",
stateInfo: currentState,

View file

@ -32,6 +32,7 @@ program
)
.option("--ephemeral", "Run without persisting state (uses temporary storage)", false)
.option("--no-tui", "Disable TUI, use plain text output")
.option("--profile-renders", "Enable render performance profiling (writes to ~/.roo/cli-render.log)", false)
.action(run)
const authCommand = program.command("auth").description("Manage authentication for Roo Code Cloud")

View file

@ -32,6 +32,8 @@ export type FlagOptions = {
waitOnComplete: boolean
ephemeral: boolean
tui: boolean
/** Enable render performance profiling (writes to ~/.roo/cli-render.log) */
profileRenders: boolean
}
export enum OnboardingProviderChoice {

View file

@ -23,6 +23,7 @@ import {
useFollowupCountdown,
useFocusManagement,
usePickerHandlers,
useRenderProfiler,
} from "./hooks/index.js"
// Import extracted utilities
@ -97,6 +98,13 @@ function AppInner({
}: TUIAppProps) {
const { exit } = useApp()
// Profile renders for the root App component
useRenderProfiler({
name: "AppInner",
trackProps: true,
props: { isLoading: false, hasMessages: false }, // Simplified - actual values tracked below
})
const {
messages,
pendingAsk,

View file

@ -5,6 +5,7 @@ import * as theme from "../theme.js"
import type { TUIMessage } from "../types.js"
import TodoDisplay from "./TodoDisplay.js"
import { getToolRenderer } from "./tools/index.js"
import { useRenderProfiler } from "../hooks/useRenderProfiler.js"
/**
* Tool categories for styling
@ -174,6 +175,15 @@ interface ChatHistoryItemProps {
}
function ChatHistoryItem({ message }: ChatHistoryItemProps) {
// Profile renders for this frequently-rendered component
useRenderProfiler({
name: "ChatHistoryItem",
trackProps: true,
props: { messageId: message.id, role: message.role, partial: message.partial },
propsToTrack: ["messageId", "role", "partial"],
warnOnFrequentRenders: 20, // Warn if > 20 renders/sec for a single message
})
const content = sanitizeContent(message.content || "...")
switch (message.role) {

View file

@ -2,6 +2,7 @@ import { Box, DOMElement, measureElement, Text, useInput } from "ink"
import { useEffect, useReducer, useRef, useCallback, useMemo, useState } from "react"
import * as theme from "../theme.js"
import { useRenderProfiler } from "../hooks/useRenderProfiler.js"
interface ScrollAreaState {
innerHeight: number
@ -177,6 +178,14 @@ export function ScrollArea({
showScrollbar = true,
autoScroll: autoScrollProp = true,
}: ScrollAreaProps) {
// Profile renders for this component (has 100ms polling interval)
useRenderProfiler({
name: "ScrollArea",
trackProps: true,
props: { isActive, showBorder, autoScroll: autoScrollProp },
propsToTrack: ["isActive", "showBorder", "autoScroll"],
})
// Ref for measuring outer container height when not provided
const outerRef = useRef<DOMElement>(null)
const [measuredHeight, setMeasuredHeight] = useState(0)

View file

@ -12,6 +12,9 @@ export { useTaskSubmit } from "./useTaskSubmit.js"
export { useGlobalInput } from "./useGlobalInput.js"
export { usePickerHandlers } from "./usePickerHandlers.js"
// Profiling hooks
export { useRenderProfiler, withRenderProfiler } from "./useRenderProfiler.js"
// Export types
export type { UseFollowupCountdownOptions } from "./useFollowupCountdown.js"
export type { UseFocusManagementOptions, UseFocusManagementReturn } from "./useFocusManagement.js"
@ -20,3 +23,4 @@ export type { UseExtensionHostOptions, UseExtensionHostReturn } from "./useExten
export type { UseTaskSubmitOptions, UseTaskSubmitReturn } from "./useTaskSubmit.js"
export type { UseGlobalInputOptions } from "./useGlobalInput.js"
export type { UsePickerHandlersOptions, UsePickerHandlersReturn } from "./usePickerHandlers.js"
export type { UseRenderProfilerOptions } from "./useRenderProfiler.js"

View file

@ -0,0 +1,212 @@
/**
* useRenderProfiler - Hook for component-level render profiling
*
* Tracks render count, timing, and optionally identifies which props
* changed to cause the re-render. Only active when profiling is enabled.
*
* Usage:
* function MyComponent(props: Props) {
* useRenderProfiler({
* name: 'MyComponent',
* trackProps: true,
* props, // Pass current props for diffing
* propsToTrack: ['id', 'content'] // Optional: limit which props to track
* })
* // ... rest of component
* }
*/
import React, { useRef, useEffect } from "react"
import { RenderProfiler } from "../utils/renderProfiler.js"
export interface UseRenderProfilerOptions {
/** Component name for logging */
name: string
/** Whether to track which props changed */
trackProps?: boolean
/** Current props object (required if trackProps is true) */
props?: Record<string, unknown>
/** Specific prop names to track (if not provided, tracks all) */
propsToTrack?: string[]
/** Warn if component renders more than N times per second */
warnOnFrequentRenders?: number
}
interface RenderStats {
count: number
lastRenderTime: number
rendersInLastSecond: number
lastSecondStart: number
}
/**
* Get a value from a nested object using dot notation path
* e.g., getNestedValue({ a: { b: 1 } }, 'a.b') => 1
*/
function getNestedValue(obj: Record<string, unknown>, path: string): unknown {
const parts = path.split(".")
let current: unknown = obj
for (const part of parts) {
if (current === null || current === undefined) return undefined
if (typeof current !== "object") return undefined
current = (current as Record<string, unknown>)[part]
}
return current
}
/**
* Compare two values for equality (shallow)
*/
function valuesEqual(a: unknown, b: unknown): boolean {
// Handle arrays - compare by reference (shallow)
if (Array.isArray(a) && Array.isArray(b)) {
return a === b
}
// Handle objects - compare by reference (shallow)
if (typeof a === "object" && typeof b === "object") {
return a === b
}
return a === b
}
/**
* Find which props changed between renders
*/
function findChangedProps(
prevProps: Record<string, unknown>,
nextProps: Record<string, unknown>,
propsToTrack?: string[],
): string[] {
const changed: string[] = []
const keysToCheck = propsToTrack || [...new Set([...Object.keys(prevProps), ...Object.keys(nextProps)])]
for (const key of keysToCheck) {
const prevValue = propsToTrack ? getNestedValue(prevProps, key) : prevProps[key]
const nextValue = propsToTrack ? getNestedValue(nextProps, key) : nextProps[key]
if (!valuesEqual(prevValue, nextValue)) {
changed.push(key)
}
}
return changed
}
/**
* Hook to profile component renders
*
* This hook tracks:
* - Total render count
* - Time since last render
* - Which props changed (if trackProps enabled)
* - Frequency warnings (if warnOnFrequentRenders set)
*/
export function useRenderProfiler(options: UseRenderProfilerOptions): void {
const { name, trackProps = false, props, propsToTrack, warnOnFrequentRenders } = options
const profiler = RenderProfiler.getInstance()
const renderStartTime = useRef<number>(performance.now())
const statsRef = useRef<RenderStats>({
count: 0,
lastRenderTime: 0,
rendersInLastSecond: 0,
lastSecondStart: Date.now(),
})
const prevPropsRef = useRef<Record<string, unknown> | null>(null)
const isFirstRender = useRef(true)
// Record render timing at the start
renderStartTime.current = performance.now()
// Track props changes
useEffect(() => {
// Skip if profiling is disabled
if (!profiler.isEnabled()) {
return
}
const stats = statsRef.current
const now = Date.now()
const renderDuration = performance.now() - renderStartTime.current
// Update render count
stats.count++
// Track renders per second
if (now - stats.lastSecondStart >= 1000) {
// Reset counter for new second
stats.rendersInLastSecond = 1
stats.lastSecondStart = now
} else {
stats.rendersInLastSecond++
}
// Determine render reason
let reason: string | undefined
if (isFirstRender.current) {
reason = "initial mount"
isFirstRender.current = false
} else if (trackProps && props && prevPropsRef.current) {
const changedProps = findChangedProps(prevPropsRef.current, props, propsToTrack)
if (changedProps.length > 0) {
reason = `props changed: ${changedProps.join(", ")}`
} else {
reason = "parent re-render (no prop changes)"
}
}
// Record the render
profiler.recordRender(name, renderDuration, reason)
// Warn on frequent renders
if (warnOnFrequentRenders && stats.rendersInLastSecond > warnOnFrequentRenders) {
profiler.recordRender(
name,
renderDuration,
`WARNING: ${stats.rendersInLastSecond} renders in last second (threshold: ${warnOnFrequentRenders})`,
)
}
// Store current props for next comparison
if (trackProps && props) {
// Shallow copy the props for comparison
prevPropsRef.current = { ...props }
}
stats.lastRenderTime = now
})
// Cleanup on unmount
useEffect(() => {
return () => {
// Nothing to clean up - profiler is a singleton
}
}, [])
}
/**
* Higher-order component wrapper for profiling class components or
* components where you can't use hooks directly.
*
* Usage:
* const ProfiledComponent = withRenderProfiler(MyComponent, 'MyComponent')
*/
export function withRenderProfiler<P extends Record<string, unknown>>(
Component: React.ComponentType<P>,
name: string,
options?: Omit<UseRenderProfilerOptions, "name" | "props">,
): React.ComponentType<P> {
const ProfiledComponent = (props: P) => {
useRenderProfiler({
name,
...options,
props: props as Record<string, unknown>,
})
return React.createElement(Component, props)
}
ProfiledComponent.displayName = `Profiled(${name})`
return ProfiledComponent
}

View file

@ -0,0 +1,139 @@
/**
* Tests for FrameTimingTracker utility
*/
import {
FrameTimingTracker,
getFrameTimingTracker,
startFrameTracking,
stopFrameTracking,
getFrameStats,
} from "../frameTiming.js"
import { RenderProfiler } from "../renderProfiler.js"
describe("FrameTimingTracker", () => {
let tracker: FrameTimingTracker
beforeEach(() => {
tracker = new FrameTimingTracker(16)
RenderProfiler.resetInstance()
})
afterEach(() => {
tracker.stop()
RenderProfiler.resetInstance()
})
describe("constructor", () => {
it("should create tracker with default threshold", () => {
const defaultTracker = new FrameTimingTracker()
const stats = defaultTracker.getStats()
expect(stats.threshold).toBe(16)
})
it("should create tracker with custom threshold", () => {
const customTracker = new FrameTimingTracker(33)
const stats = customTracker.getStats()
expect(stats.threshold).toBe(33)
})
})
describe("start/stop", () => {
it("should start tracking", () => {
expect(tracker.isRunning()).toBe(false)
tracker.start()
expect(tracker.isRunning()).toBe(true)
})
it("should stop tracking", () => {
tracker.start()
expect(tracker.isRunning()).toBe(true)
tracker.stop()
expect(tracker.isRunning()).toBe(false)
})
it("should not start multiple times", () => {
tracker.start()
tracker.start() // Should not throw
expect(tracker.isRunning()).toBe(true)
})
})
describe("getStats", () => {
it("should return empty stats when no measurements", () => {
const stats = tracker.getStats()
expect(stats.measurements).toBe(0)
expect(stats.avgMs).toBe(0)
expect(stats.maxMs).toBe(0)
expect(stats.p95Ms).toBe(0)
expect(stats.droppedFrames).toBe(0)
})
})
describe("reset", () => {
it("should clear measurements", async () => {
tracker.start()
// Wait for some measurements
await new Promise((resolve) => setTimeout(resolve, 50))
tracker.stop()
const statsBefore = tracker.getStats()
expect(statsBefore.measurements).toBeGreaterThan(0)
tracker.reset()
const statsAfter = tracker.getStats()
expect(statsAfter.measurements).toBe(0)
})
})
})
describe("Global frame tracking functions", () => {
afterEach(() => {
stopFrameTracking()
RenderProfiler.resetInstance()
})
describe("getFrameTimingTracker", () => {
it("should return singleton tracker", () => {
const tracker1 = getFrameTimingTracker()
const tracker2 = getFrameTimingTracker()
expect(tracker1).toBe(tracker2)
})
})
describe("startFrameTracking", () => {
it("should start global tracker", () => {
startFrameTracking()
const tracker = getFrameTimingTracker()
expect(tracker.isRunning()).toBe(true)
})
it("should not start if already running", () => {
startFrameTracking()
startFrameTracking() // Should not throw
expect(getFrameTimingTracker().isRunning()).toBe(true)
})
})
describe("stopFrameTracking", () => {
it("should stop global tracker", () => {
startFrameTracking()
stopFrameTracking()
expect(getFrameTimingTracker().isRunning()).toBe(false)
})
it("should handle stop when not started", () => {
stopFrameTracking() // Should not throw
})
})
describe("getFrameStats", () => {
it("should return null when no tracker exists", () => {
// Note: This test may need adjustment since getFrameTimingTracker creates the tracker
const stats = getFrameStats()
// Stats should exist but have 0 measurements
expect(stats?.measurements).toBe(0)
})
})
})

View file

@ -0,0 +1,231 @@
/**
* Tests for RenderProfiler utility
*/
import * as fs from "fs"
import * as os from "os"
import { RenderProfiler, getRenderLogPath, isProfilingEnabled } from "../renderProfiler.js"
// Mock fs module
vi.mock("fs", async () => {
const actual = await vi.importActual<typeof fs>("fs")
return {
...actual,
existsSync: vi.fn(() => true),
mkdirSync: vi.fn(),
appendFileSync: vi.fn(),
}
})
describe("RenderProfiler", () => {
beforeEach(() => {
// Reset singleton between tests
RenderProfiler.resetInstance()
vi.clearAllMocks()
})
afterEach(() => {
RenderProfiler.resetInstance()
})
describe("getInstance", () => {
it("should return the same instance (singleton)", () => {
const instance1 = RenderProfiler.getInstance()
const instance2 = RenderProfiler.getInstance()
expect(instance1).toBe(instance2)
})
})
describe("configure", () => {
it("should enable profiling when configured", () => {
const profiler = RenderProfiler.getInstance()
expect(profiler.isEnabled()).toBe(false)
profiler.configure({ enabled: true })
expect(profiler.isEnabled()).toBe(true)
})
it("should merge partial configuration", () => {
const profiler = RenderProfiler.getInstance()
profiler.configure({ enabled: true, slowRenderThreshold: 32 })
const config = profiler.getConfig()
expect(config.enabled).toBe(true)
expect(config.slowRenderThreshold).toBe(32)
expect(config.aggregateInterval).toBe(5000) // default
})
it("should write config log when enabled", () => {
const profiler = RenderProfiler.getInstance()
profiler.configure({ enabled: true })
expect(fs.appendFileSync).toHaveBeenCalled()
})
})
describe("recordRender", () => {
it("should not record when profiling is disabled", () => {
const profiler = RenderProfiler.getInstance()
profiler.recordRender("TestComponent", 5.0, "test reason")
const summary = profiler.getSummary()
expect(summary.totalRenders).toBe(0)
})
it("should record render events when enabled", () => {
const profiler = RenderProfiler.getInstance()
profiler.configure({ enabled: true, logComponents: false })
profiler.recordRender("TestComponent", 5.0, "test reason")
profiler.recordRender("TestComponent", 3.0)
profiler.recordRender("OtherComponent", 2.0)
const summary = profiler.getSummary()
expect(summary.totalRenders).toBe(3)
expect(summary.componentBreakdown["TestComponent"]).toBeDefined()
expect(summary.componentBreakdown["TestComponent"]?.count).toBe(2)
expect(summary.componentBreakdown["OtherComponent"]?.count).toBe(1)
})
it("should calculate average and max times correctly", () => {
const profiler = RenderProfiler.getInstance()
profiler.configure({ enabled: true, logComponents: false })
profiler.recordRender("TestComponent", 2.0)
profiler.recordRender("TestComponent", 4.0)
profiler.recordRender("TestComponent", 6.0)
const summary = profiler.getSummary()
expect(summary.componentBreakdown["TestComponent"]?.avgMs).toBe(4)
expect(summary.componentBreakdown["TestComponent"]?.maxMs).toBe(6)
})
})
describe("recordStoreUpdate", () => {
it("should not record when profiling is disabled", () => {
const profiler = RenderProfiler.getInstance()
profiler.recordStoreUpdate("TestStore", "set", 1.0)
const summary = profiler.getSummary()
expect(Object.keys(summary.storeUpdates)).toHaveLength(0)
})
it("should record store updates when enabled", () => {
const profiler = RenderProfiler.getInstance()
profiler.configure({ enabled: true, logStoreUpdates: false })
profiler.recordStoreUpdate("CLIStore", "set(messages)", 1.5)
profiler.recordStoreUpdate("CLIStore", "set(messages)", 2.0)
profiler.recordStoreUpdate("UIStore", "set(focus)", 0.5)
const summary = profiler.getSummary()
expect(summary.storeUpdates["CLIStore:set(messages)"]?.count).toBe(2)
expect(summary.storeUpdates["UIStore:set(focus)"]?.count).toBe(1)
})
})
describe("recordFrameTime", () => {
it("should record frame timing when enabled", () => {
const profiler = RenderProfiler.getInstance()
profiler.configure({ enabled: true, logFrameTiming: false })
profiler.recordFrameTime(8.0)
profiler.recordFrameTime(16.0)
profiler.recordFrameTime(32.0)
const stats = profiler.getFrameStats()
expect(stats).not.toBeNull()
expect(stats?.measurements).toBe(3)
expect(stats?.avgMs).toBeCloseTo(18.67, 1)
expect(stats?.maxMs).toBe(32)
})
it("should limit measurements to 1000", () => {
const profiler = RenderProfiler.getInstance()
profiler.configure({ enabled: true, logFrameTiming: false })
// Add 1100 measurements
for (let i = 0; i < 1100; i++) {
profiler.recordFrameTime(10.0)
}
const stats = profiler.getFrameStats()
expect(stats?.measurements).toBe(1000)
})
})
describe("getSummary", () => {
it("should return empty summary when no data", () => {
const profiler = RenderProfiler.getInstance()
profiler.configure({ enabled: true })
const summary = profiler.getSummary()
expect(summary.totalRenders).toBe(0)
expect(Object.keys(summary.componentBreakdown)).toHaveLength(0)
expect(Object.keys(summary.storeUpdates)).toHaveLength(0)
})
})
describe("reset", () => {
it("should clear all accumulated data", () => {
const profiler = RenderProfiler.getInstance()
profiler.configure({ enabled: true, logComponents: false, logStoreUpdates: false })
profiler.recordRender("TestComponent", 5.0)
profiler.recordStoreUpdate("TestStore", "set", 1.0)
profiler.recordFrameTime(10.0)
let summary = profiler.getSummary()
expect(summary.totalRenders).toBe(1)
profiler.reset()
summary = profiler.getSummary()
expect(summary.totalRenders).toBe(0)
expect(Object.keys(summary.storeUpdates)).toHaveLength(0)
expect(profiler.getFrameStats()).toBeNull()
})
})
describe("stop", () => {
it("should flush data and stop timers", () => {
const profiler = RenderProfiler.getInstance()
profiler.configure({ enabled: true, logComponents: false })
profiler.recordRender("TestComponent", 5.0)
profiler.stop()
// After stop, data should be reset
const summary = profiler.getSummary()
expect(summary.totalRenders).toBe(0)
})
})
})
describe("isProfilingEnabled", () => {
beforeEach(() => {
RenderProfiler.resetInstance()
})
afterEach(() => {
RenderProfiler.resetInstance()
})
it("should return false when profiler is not enabled", () => {
expect(isProfilingEnabled()).toBe(false)
})
it("should return true when profiler is enabled", () => {
RenderProfiler.getInstance().configure({ enabled: true })
expect(isProfilingEnabled()).toBe(true)
})
})
describe("getRenderLogPath", () => {
it("should return path in home directory", () => {
const logPath = getRenderLogPath()
expect(logPath).toContain(os.homedir())
expect(logPath).toContain(".roo")
expect(logPath).toContain("cli-render.log")
})
})

View file

@ -0,0 +1,191 @@
/**
* Frame Timing Tracker
*
* Monitors event loop delay to detect blocking renders and long tasks.
* Uses setImmediate to measure how long the event loop takes between ticks.
*
* Usage:
* import { FrameTimingTracker } from "./frameTiming.js"
*
* const tracker = new FrameTimingTracker()
* tracker.start()
* // ... later
* tracker.stop()
* console.log(tracker.getStats())
*/
import { RenderProfiler } from "./renderProfiler.js"
export interface FrameStats {
/** Average frame time in ms */
avgMs: number
/** Maximum frame time in ms */
maxMs: number
/** 95th percentile frame time in ms */
p95Ms: number
/** Total number of measurements */
measurements: number
/** Number of frames exceeding threshold */
droppedFrames: number
/** Target frame time threshold in ms */
threshold: number
}
export class FrameTimingTracker {
private lastTick: number = 0
private measurements: number[] = []
private running: boolean = false
private immediateId: NodeJS.Immediate | null = null
private threshold: number
/**
* Create a new frame timing tracker
* @param thresholdMs - Frame time threshold for "dropped frame" detection (default: 16ms = 60fps)
*/
constructor(thresholdMs: number = 16) {
this.threshold = thresholdMs
}
/**
* Start tracking frame timing
*/
start(): void {
if (this.running) return
this.running = true
this.lastTick = performance.now()
this.measurements = []
this.scheduleNextMeasurement()
}
/**
* Stop tracking frame timing
*/
stop(): void {
this.running = false
if (this.immediateId) {
clearImmediate(this.immediateId)
this.immediateId = null
}
}
/**
* Check if tracker is currently running
*/
isRunning(): boolean {
return this.running
}
/**
* Get current frame timing statistics
*/
getStats(): FrameStats {
if (this.measurements.length === 0) {
return {
avgMs: 0,
maxMs: 0,
p95Ms: 0,
measurements: 0,
droppedFrames: 0,
threshold: this.threshold,
}
}
const sorted = [...this.measurements].sort((a, b) => a - b)
const sum = sorted.reduce((a, b) => a + b, 0)
const p95Index = Math.floor(sorted.length * 0.95)
return {
avgMs: Math.round((sum / sorted.length) * 100) / 100,
maxMs: Math.round((sorted[sorted.length - 1] ?? 0) * 100) / 100,
p95Ms: Math.round((sorted[p95Index] ?? 0) * 100) / 100,
measurements: sorted.length,
droppedFrames: this.measurements.filter((t) => t > this.threshold).length,
threshold: this.threshold,
}
}
/**
* Reset collected measurements
*/
reset(): void {
this.measurements = []
this.lastTick = performance.now()
}
/**
* Schedule the next measurement using setImmediate
*/
private scheduleNextMeasurement(): void {
if (!this.running) return
this.immediateId = setImmediate(() => {
this.measure()
this.scheduleNextMeasurement()
})
}
/**
* Perform a single measurement
*/
private measure(): void {
const now = performance.now()
const delta = now - this.lastTick
this.lastTick = now
// Record measurement
this.measurements.push(delta)
// Keep only last 1000 measurements to bound memory
if (this.measurements.length > 1000) {
this.measurements = this.measurements.slice(-1000)
}
// Record to profiler
const profiler = RenderProfiler.getInstance()
if (profiler.isEnabled()) {
profiler.recordFrameTime(delta)
}
}
}
// Singleton instance for global frame timing
let globalTracker: FrameTimingTracker | null = null
/**
* Get or create the global frame timing tracker
*/
export function getFrameTimingTracker(): FrameTimingTracker {
if (!globalTracker) {
globalTracker = new FrameTimingTracker()
}
return globalTracker
}
/**
* Start global frame timing tracking
* Automatically starts when profiling is enabled
*/
export function startFrameTracking(): void {
const tracker = getFrameTimingTracker()
if (!tracker.isRunning()) {
tracker.start()
}
}
/**
* Stop global frame timing tracking
*/
export function stopFrameTracking(): void {
if (globalTracker) {
globalTracker.stop()
}
}
/**
* Get global frame timing stats
*/
export function getFrameStats(): FrameStats | null {
if (!globalTracker) return null
return globalTracker.getStats()
}

View file

@ -1,2 +1,7 @@
export * from "./tools.js"
export * from "./views.js"
// Profiling utilities
export * from "./renderProfiler.js"
export * from "./storeProfiler.js"
export * from "./frameTiming.js"

View file

@ -0,0 +1,477 @@
/**
* Render Performance Profiler
*
* A singleton class that collects and aggregates render performance data
* for the CLI TUI application. Writes to ~/.roo/cli-render.log to avoid
* corrupting TUI output.
*
* Usage:
* import { RenderProfiler } from './utils/renderProfiler.js'
*
* // Get singleton instance
* const profiler = RenderProfiler.getInstance()
*
* // Record a component render
* profiler.recordRender('ChatHistoryItem', 2.5, 'props.message.content changed')
*
* // Record a store update
* profiler.recordStoreUpdate('CLIStore', 'addMessage', 0.8)
*/
import * as fs from "fs"
import * as path from "path"
import * as os from "os"
const RENDER_LOG_PATH = path.join(os.homedir(), ".roo", "cli-render.log")
export interface RenderProfilerConfig {
/** Enable/disable profiling globally */
enabled: boolean
/** Log individual component render events */
logComponents: boolean
/** Log Zustand store updates */
logStoreUpdates: boolean
/** Log frame/tick timing */
logFrameTiming: boolean
/** Milliseconds between aggregate summary logs (default: 5000) */
aggregateInterval: number
/** Threshold in ms for slow render warnings (default: 16 - one frame at 60fps) */
slowRenderThreshold: number
}
export interface RenderEvent {
component: string
renderCount: number
totalTime: number
avgTime: number
maxTime: number
lastReason?: string
}
export interface StoreUpdateEvent {
store: string
action: string
count: number
totalTime: number
avgTime: number
maxTime: number
}
export interface FrameTimingStats {
avgMs: number
maxMs: number
p95Ms: number
measurements: number
droppedFrames: number
}
export interface ProfilerSummary {
periodMs: number
totalRenders: number
componentBreakdown: Record<string, { count: number; avgMs: number; maxMs: number }>
storeUpdates: Record<string, { count: number; avgMs: number; maxMs: number }>
frameTiming: FrameTimingStats | null
}
interface LogEntry {
timestamp: string
type: "render" | "store_update" | "frame" | "summary" | "config"
[key: string]: unknown
}
const defaultConfig: RenderProfilerConfig = {
enabled: false,
logComponents: true,
logStoreUpdates: true,
logFrameTiming: true,
aggregateInterval: 5000,
slowRenderThreshold: 16,
}
export class RenderProfiler {
private static instance: RenderProfiler | null = null
private config: RenderProfilerConfig
private renderEvents: Map<string, RenderEvent> = new Map()
private storeUpdates: Map<string, StoreUpdateEvent> = new Map()
private frameTimings: number[] = []
private lastSummaryTime: number = 0
private summaryTimer: NodeJS.Timeout | null = null
private logBuffer: LogEntry[] = []
private flushTimer: NodeJS.Timeout | null = null
private startTime: number = Date.now()
private constructor() {
this.config = { ...defaultConfig }
}
/**
* Get the singleton instance of RenderProfiler
*/
static getInstance(): RenderProfiler {
if (!RenderProfiler.instance) {
RenderProfiler.instance = new RenderProfiler()
}
return RenderProfiler.instance
}
/**
* Reset the singleton instance (useful for testing)
*/
static resetInstance(): void {
if (RenderProfiler.instance) {
RenderProfiler.instance.stop()
RenderProfiler.instance = null
}
}
/**
* Configure the profiler
*/
configure(config: Partial<RenderProfilerConfig>): void {
const wasEnabled = this.config.enabled
this.config = { ...this.config, ...config }
// Log configuration change
if (this.config.enabled) {
this.writeLog({
timestamp: new Date().toISOString(),
type: "config",
config: this.config,
})
}
// Start/stop summary timer based on enabled state
if (this.config.enabled && !wasEnabled) {
this.startSummaryTimer()
this.lastSummaryTime = Date.now()
this.startTime = Date.now()
} else if (!this.config.enabled && wasEnabled) {
this.stop()
}
}
/**
* Check if profiling is enabled
*/
isEnabled(): boolean {
return this.config.enabled
}
/**
* Get current configuration
*/
getConfig(): RenderProfilerConfig {
return { ...this.config }
}
/**
* Record a component render event
*/
recordRender(component: string, durationMs: number, reason?: string): void {
if (!this.config.enabled) return
// Update aggregated stats
const existing = this.renderEvents.get(component)
if (existing) {
existing.renderCount++
existing.totalTime += durationMs
existing.avgTime = existing.totalTime / existing.renderCount
existing.maxTime = Math.max(existing.maxTime, durationMs)
if (reason) existing.lastReason = reason
} else {
this.renderEvents.set(component, {
component,
renderCount: 1,
totalTime: durationMs,
avgTime: durationMs,
maxTime: durationMs,
lastReason: reason,
})
}
// Log individual event if configured
if (this.config.logComponents) {
const entry: LogEntry = {
timestamp: new Date().toISOString(),
type: "render",
component,
duration: durationMs,
}
if (reason) entry.reason = reason
// Warn on slow renders
if (durationMs > this.config.slowRenderThreshold) {
entry.slow = true
}
this.bufferLog(entry)
}
}
/**
* Record props that changed for a component
*/
recordPropsChange(component: string, changedProps: string[]): void {
if (!this.config.enabled || !this.config.logComponents) return
this.bufferLog({
timestamp: new Date().toISOString(),
type: "render",
component,
propsChanged: changedProps,
})
}
/**
* Record a store update event
*/
recordStoreUpdate(store: string, action: string, durationMs: number): void {
if (!this.config.enabled) return
const key = `${store}:${action}`
const existing = this.storeUpdates.get(key)
if (existing) {
existing.count++
existing.totalTime += durationMs
existing.avgTime = existing.totalTime / existing.count
existing.maxTime = Math.max(existing.maxTime, durationMs)
} else {
this.storeUpdates.set(key, {
store,
action,
count: 1,
totalTime: durationMs,
avgTime: durationMs,
maxTime: durationMs,
})
}
// Log individual event if configured
if (this.config.logStoreUpdates) {
this.bufferLog({
timestamp: new Date().toISOString(),
type: "store_update",
store,
action,
duration: durationMs,
})
}
}
/**
* Record a frame timing measurement
*/
recordFrameTime(durationMs: number): void {
if (!this.config.enabled) return
this.frameTimings.push(durationMs)
// Keep only last 1000 measurements to bound memory
if (this.frameTimings.length > 1000) {
this.frameTimings = this.frameTimings.slice(-1000)
}
// Log individual slow frames
if (this.config.logFrameTiming && durationMs > this.config.slowRenderThreshold) {
this.bufferLog({
timestamp: new Date().toISOString(),
type: "frame",
duration: durationMs,
slow: true,
})
}
}
/**
* Get frame timing statistics
*/
getFrameStats(): FrameTimingStats | null {
if (this.frameTimings.length === 0) return null
const sorted = [...this.frameTimings].sort((a, b) => a - b)
const sum = sorted.reduce((a, b) => a + b, 0)
const p95Index = Math.floor(sorted.length * 0.95)
return {
avgMs: sum / sorted.length,
maxMs: sorted[sorted.length - 1] ?? 0,
p95Ms: sorted[p95Index] ?? 0,
measurements: sorted.length,
droppedFrames: this.frameTimings.filter((t) => t > this.config.slowRenderThreshold).length,
}
}
/**
* Get current summary of profiling data
*/
getSummary(): ProfilerSummary {
const now = Date.now()
const periodMs = now - this.lastSummaryTime
const componentBreakdown: Record<string, { count: number; avgMs: number; maxMs: number }> = {}
let totalRenders = 0
for (const [name, event] of this.renderEvents) {
componentBreakdown[name] = {
count: event.renderCount,
avgMs: Math.round(event.avgTime * 100) / 100,
maxMs: Math.round(event.maxTime * 100) / 100,
}
totalRenders += event.renderCount
}
const storeUpdates: Record<string, { count: number; avgMs: number; maxMs: number }> = {}
for (const [key, event] of this.storeUpdates) {
storeUpdates[key] = {
count: event.count,
avgMs: Math.round(event.avgTime * 100) / 100,
maxMs: Math.round(event.maxTime * 100) / 100,
}
}
return {
periodMs,
totalRenders,
componentBreakdown,
storeUpdates,
frameTiming: this.getFrameStats(),
}
}
/**
* Flush buffered logs to file and write summary
*/
flush(): void {
if (!this.config.enabled) return
// Write buffered logs
this.flushBuffer()
// Write summary
const summary = this.getSummary()
this.writeLog({
timestamp: new Date().toISOString(),
type: "summary",
period: `${Math.round(summary.periodMs / 1000)}s`,
totalRenders: summary.totalRenders,
componentBreakdown: summary.componentBreakdown,
storeUpdates: summary.storeUpdates,
frameTiming: summary.frameTiming,
})
// Reset for next period
this.reset()
this.lastSummaryTime = Date.now()
}
/**
* Reset accumulated statistics (but keep profiler enabled)
*/
reset(): void {
this.renderEvents.clear()
this.storeUpdates.clear()
this.frameTimings = []
}
/**
* Stop profiling and clean up
*/
stop(): void {
if (this.summaryTimer) {
clearInterval(this.summaryTimer)
this.summaryTimer = null
}
if (this.flushTimer) {
clearTimeout(this.flushTimer)
this.flushTimer = null
}
// Final flush if we have data
if (this.logBuffer.length > 0 || this.renderEvents.size > 0) {
this.flush()
}
this.reset()
}
/**
* Buffer a log entry for batch writing
*/
private bufferLog(entry: LogEntry): void {
this.logBuffer.push(entry)
// Schedule flush if not already scheduled
if (!this.flushTimer) {
this.flushTimer = setTimeout(() => {
this.flushBuffer()
this.flushTimer = null
}, 100) // Flush every 100ms max
}
}
/**
* Write buffered logs to file
*/
private flushBuffer(): void {
if (this.logBuffer.length === 0) return
try {
const logDir = path.dirname(RENDER_LOG_PATH)
if (!fs.existsSync(logDir)) {
fs.mkdirSync(logDir, { recursive: true })
}
const lines = this.logBuffer.map((entry) => JSON.stringify(entry)).join("\n") + "\n"
fs.appendFileSync(RENDER_LOG_PATH, lines)
this.logBuffer = []
} catch {
// NO-OP - don't let logging errors break functionality
}
}
/**
* Write a single log entry immediately
*/
private writeLog(entry: LogEntry): void {
try {
const logDir = path.dirname(RENDER_LOG_PATH)
if (!fs.existsSync(logDir)) {
fs.mkdirSync(logDir, { recursive: true })
}
fs.appendFileSync(RENDER_LOG_PATH, JSON.stringify(entry) + "\n")
} catch {
// NO-OP - don't let logging errors break functionality
}
}
/**
* Start the periodic summary timer
*/
private startSummaryTimer(): void {
if (this.summaryTimer) {
clearInterval(this.summaryTimer)
}
this.summaryTimer = setInterval(() => {
this.flush()
}, this.config.aggregateInterval)
// Don't prevent process exit
this.summaryTimer.unref()
}
}
/**
* Convenience function to check if profiling is enabled
*/
export function isProfilingEnabled(): boolean {
return RenderProfiler.getInstance().isEnabled()
}
/**
* Get the render log file path
*/
export function getRenderLogPath(): string {
return RENDER_LOG_PATH
}

View file

@ -0,0 +1,156 @@
/**
* Zustand Store Profiler
*
* Wraps existing Zustand stores to profile state updates.
* Only active when profiling is enabled.
*
* Usage:
* import { wrapStoreWithProfiler } from "./storeProfiler.js"
*
* // After store creation, wrap it for profiling
* wrapStoreWithProfiler(useMyStore, "MyStore")
*/
import { RenderProfiler } from "./renderProfiler.js"
/**
* Find which keys changed between two state objects
*/
function findChangedKeys<T extends object>(prev: T, next: T): string[] {
const changed: string[] = []
const allKeys = new Set([...Object.keys(prev), ...Object.keys(next)])
for (const key of allKeys) {
const prevValue = (prev as Record<string, unknown>)[key]
const nextValue = (next as Record<string, unknown>)[key]
// Shallow comparison
if (prevValue !== nextValue) {
changed.push(key)
}
}
return changed
}
/**
* Type for a Zustand store that has getState and setState methods
* Using loose typing to handle Zustand's complex overloaded setState signature
*/
interface ZustandLikeStore {
getState: () => unknown
// eslint-disable-next-line @typescript-eslint/no-explicit-any
setState: (...args: any[]) => void
}
/**
* Wrap an existing Zustand store with profiling
*
* This wraps the store's setState method to measure duration
* and track which state keys changed.
*
* @param store - The Zustand store hook (has getState/setState)
* @param storeName - Name for logging
*/
export function wrapStoreWithProfiler(store: ZustandLikeStore, storeName: string): void {
const originalSetState = store.setState.bind(store)
// eslint-disable-next-line @typescript-eslint/no-explicit-any
store.setState = (...args: any[]) => {
const [partial, replace] = args
const profiler = RenderProfiler.getInstance()
// Fast path: if profiling is disabled, just call original
if (!profiler.isEnabled()) {
return originalSetState(partial, replace)
}
const start = performance.now()
const prevState = store.getState()
// Call original setState
originalSetState(partial, replace)
const duration = performance.now() - start
const nextState = store.getState()
// Find what changed
const changedKeys = findChangedKeys(prevState as object, nextState as object)
// Determine action name from the partial
let actionName = "setState"
if (typeof partial === "object" && partial !== null) {
const keys = Object.keys(partial)
if (keys.length <= 3) {
actionName = `set(${keys.join(",")})`
} else {
actionName = `set(${keys.length} keys)`
}
} else if (typeof partial === "function") {
actionName = "set(fn)"
}
// Record the update
profiler.recordStoreUpdate(storeName, actionName, duration)
// Log changed keys (as separate record with 0 duration to avoid double-counting)
if (changedKeys.length > 0 && changedKeys.length <= 5) {
profiler.recordStoreUpdate(storeName, `${changedKeys.join(",")}`, 0)
}
}
}
/**
* Create a logging wrapper for setState that can be used manually
*
* Usage:
* const profiledSet = createProfiledSetState(set, "MyStore")
* // Use profiledSet instead of set
*/
export function createProfiledSetState<T extends object>(
originalSet: (partial: Partial<T> | ((state: T) => Partial<T>), replace?: boolean) => void,
getState: () => T,
storeName: string,
): typeof originalSet {
return (partial, replace) => {
const profiler = RenderProfiler.getInstance()
// Fast path: if profiling is disabled, just call original
if (!profiler.isEnabled()) {
return originalSet(partial, replace)
}
const start = performance.now()
const prevState = getState()
// Call original set
originalSet(partial, replace)
const duration = performance.now() - start
const nextState = getState()
// Find what changed
const changedKeys = findChangedKeys(prevState as object, nextState as object)
// Determine action name
let actionName = "set"
if (typeof partial === "object" && partial !== null) {
const keys = Object.keys(partial)
if (keys.length <= 3) {
actionName = `set(${keys.join(",")})`
} else {
actionName = `set(${keys.length} keys)`
}
} else if (typeof partial === "function") {
actionName = "set(fn)"
}
// Record the update
profiler.recordStoreUpdate(storeName, actionName, duration)
// Log changed keys
if (changedKeys.length > 0 && changedKeys.length <= 5) {
profiler.recordStoreUpdate(storeName, `${changedKeys.join(",")}`, 0)
}
}
}