diff --git a/apps/cli/src/commands/cli/run.ts b/apps/cli/src/commands/cli/run.ts index a091271a71..06feb057ae 100644 --- a/apps/cli/src/commands/cli/run.ts +++ b/apps/cli/src/commands/cli/run.ts @@ -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 [options]") diff --git a/apps/cli/src/extension-client/message-processor.ts b/apps/cli/src/extension-client/message-processor.ts index 9d1b960155..6b941dec81 100644 --- a/apps/cli/src/extension-client/message-processor.ts +++ b/apps/cli/src/extension-client/message-processor.ts @@ -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, diff --git a/apps/cli/src/index.ts b/apps/cli/src/index.ts index fad07e6876..2fcef366e5 100644 --- a/apps/cli/src/index.ts +++ b/apps/cli/src/index.ts @@ -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") diff --git a/apps/cli/src/types/types.ts b/apps/cli/src/types/types.ts index 5fcddaf836..25a4c1c7cd 100644 --- a/apps/cli/src/types/types.ts +++ b/apps/cli/src/types/types.ts @@ -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 { diff --git a/apps/cli/src/ui/App.tsx b/apps/cli/src/ui/App.tsx index c0cb97d244..3bee8c6859 100644 --- a/apps/cli/src/ui/App.tsx +++ b/apps/cli/src/ui/App.tsx @@ -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, diff --git a/apps/cli/src/ui/components/ChatHistoryItem.tsx b/apps/cli/src/ui/components/ChatHistoryItem.tsx index 8b52a2b160..017c0f3415 100644 --- a/apps/cli/src/ui/components/ChatHistoryItem.tsx +++ b/apps/cli/src/ui/components/ChatHistoryItem.tsx @@ -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) { diff --git a/apps/cli/src/ui/components/ScrollArea.tsx b/apps/cli/src/ui/components/ScrollArea.tsx index a356125fb2..d5c0b170a4 100644 --- a/apps/cli/src/ui/components/ScrollArea.tsx +++ b/apps/cli/src/ui/components/ScrollArea.tsx @@ -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(null) const [measuredHeight, setMeasuredHeight] = useState(0) diff --git a/apps/cli/src/ui/hooks/index.ts b/apps/cli/src/ui/hooks/index.ts index 9e12cd9b0e..9130a3aa19 100644 --- a/apps/cli/src/ui/hooks/index.ts +++ b/apps/cli/src/ui/hooks/index.ts @@ -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" diff --git a/apps/cli/src/ui/hooks/useRenderProfiler.ts b/apps/cli/src/ui/hooks/useRenderProfiler.ts new file mode 100644 index 0000000000..9d5d6daac9 --- /dev/null +++ b/apps/cli/src/ui/hooks/useRenderProfiler.ts @@ -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 + /** 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, 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)[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, + nextProps: Record, + 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(performance.now()) + const statsRef = useRef({ + count: 0, + lastRenderTime: 0, + rendersInLastSecond: 0, + lastSecondStart: Date.now(), + }) + const prevPropsRef = useRef | 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

>( + Component: React.ComponentType

, + name: string, + options?: Omit, +): React.ComponentType

{ + const ProfiledComponent = (props: P) => { + useRenderProfiler({ + name, + ...options, + props: props as Record, + }) + + return React.createElement(Component, props) + } + + ProfiledComponent.displayName = `Profiled(${name})` + return ProfiledComponent +} diff --git a/apps/cli/src/ui/utils/__tests__/frameTiming.test.ts b/apps/cli/src/ui/utils/__tests__/frameTiming.test.ts new file mode 100644 index 0000000000..40c229b5af --- /dev/null +++ b/apps/cli/src/ui/utils/__tests__/frameTiming.test.ts @@ -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) + }) + }) +}) diff --git a/apps/cli/src/ui/utils/__tests__/renderProfiler.test.ts b/apps/cli/src/ui/utils/__tests__/renderProfiler.test.ts new file mode 100644 index 0000000000..f08dd52b3f --- /dev/null +++ b/apps/cli/src/ui/utils/__tests__/renderProfiler.test.ts @@ -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("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") + }) +}) diff --git a/apps/cli/src/ui/utils/frameTiming.ts b/apps/cli/src/ui/utils/frameTiming.ts new file mode 100644 index 0000000000..c66869f063 --- /dev/null +++ b/apps/cli/src/ui/utils/frameTiming.ts @@ -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() +} diff --git a/apps/cli/src/ui/utils/index.ts b/apps/cli/src/ui/utils/index.ts index 9c55726d64..386b104514 100644 --- a/apps/cli/src/ui/utils/index.ts +++ b/apps/cli/src/ui/utils/index.ts @@ -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" diff --git a/apps/cli/src/ui/utils/renderProfiler.ts b/apps/cli/src/ui/utils/renderProfiler.ts new file mode 100644 index 0000000000..d5f684734d --- /dev/null +++ b/apps/cli/src/ui/utils/renderProfiler.ts @@ -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 + storeUpdates: Record + 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 = new Map() + private storeUpdates: Map = 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): 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 = {} + 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 = {} + 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 +} diff --git a/apps/cli/src/ui/utils/storeProfiler.ts b/apps/cli/src/ui/utils/storeProfiler.ts new file mode 100644 index 0000000000..f24222ab74 --- /dev/null +++ b/apps/cli/src/ui/utils/storeProfiler.ts @@ -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(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)[key] + const nextValue = (next as Record)[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( + originalSet: (partial: Partial | ((state: T) => Partial), 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) + } + } +}