Enhance debug profiler to track tree framerate and dispatch errors (#10502)

This commit is contained in:
Jacob Richman
2025-10-07 10:28:35 -07:00
committed by GitHub
parent 6bb99806f0
commit 34ba8be821
20 changed files with 487 additions and 27 deletions
+1 -1
View File
@@ -115,7 +115,7 @@ export const defaultKeyBindings: KeyBindingConfig = {
[Command.CLEAR_SCREEN]: [{ key: 'l', ctrl: true }],
// History navigation
[Command.HISTORY_UP]: [{ key: 'p', ctrl: true }],
[Command.HISTORY_UP]: [{ key: 'p', ctrl: true, shift: false }],
[Command.HISTORY_DOWN]: [{ key: 'n', ctrl: true }],
[Command.NAVIGATION_UP]: [{ key: 'up' }],
[Command.NAVIGATION_DOWN]: [{ key: 'down' }],
@@ -4,6 +4,17 @@
* SPDX-License-Identifier: Apache-2.0
*/
vi.mock('../ui/commands/profileCommand.js', async () => {
const { CommandKind } = await import('../ui/commands/types.js');
return {
profileCommand: {
name: 'profile',
description: 'Profile command',
kind: CommandKind.BUILT_IN,
},
};
});
vi.mock('../ui/commands/aboutCommand.js', async () => {
const { CommandKind } = await import('../ui/commands/types.js');
return {
@@ -177,3 +188,34 @@ describe('BuiltinCommandLoader', () => {
expect(modelCmd).toBeUndefined();
});
});
describe('BuiltinCommandLoader profile', () => {
let mockConfig: Config;
beforeEach(() => {
vi.resetModules();
mockConfig = {
getFolderTrust: vi.fn().mockReturnValue(false),
getUseModelRouter: () => false,
getCheckpointingEnabled: () => false,
} as unknown as Config;
});
it('should not include profile command when isDevelopment is false', async () => {
process.env['NODE_ENV'] = 'production';
const { BuiltinCommandLoader } = await import('./BuiltinCommandLoader.js');
const loader = new BuiltinCommandLoader(mockConfig);
const commands = await loader.loadCommands(new AbortController().signal);
const profileCmd = commands.find((c) => c.name === 'profile');
expect(profileCmd).toBeUndefined();
});
it('should include profile command when isDevelopment is true', async () => {
process.env['NODE_ENV'] = 'development';
const { BuiltinCommandLoader } = await import('./BuiltinCommandLoader.js');
const loader = new BuiltinCommandLoader(mockConfig);
const commands = await loader.loadCommands(new AbortController().signal);
const profileCmd = commands.find((c) => c.name === 'profile');
expect(profileCmd).toBeDefined();
});
});
@@ -4,6 +4,7 @@
* SPDX-License-Identifier: Apache-2.0
*/
import { isDevelopment } from '../utils/installationInfo.js';
import type { ICommandLoader } from './types.js';
import type { SlashCommand } from '../ui/commands/types.js';
import type { Config } from '@google/gemini-cli-core';
@@ -27,6 +28,7 @@ import { memoryCommand } from '../ui/commands/memoryCommand.js';
import { modelCommand } from '../ui/commands/modelCommand.js';
import { permissionsCommand } from '../ui/commands/permissionsCommand.js';
import { privacyCommand } from '../ui/commands/privacyCommand.js';
import { profileCommand } from '../ui/commands/profileCommand.js';
import { quitCommand } from '../ui/commands/quitCommand.js';
import { restoreCommand } from '../ui/commands/restoreCommand.js';
import { statsCommand } from '../ui/commands/statsCommand.js';
@@ -73,6 +75,7 @@ export class BuiltinCommandLoader implements ICommandLoader {
...(this.config?.getUseModelRouter() ? [modelCommand] : []),
...(this.config?.getFolderTrust() ? [permissionsCommand] : []),
privacyCommand,
...(isDevelopment ? [profileCommand] : []),
quitCommand,
restoreCommand(this.config),
statsCommand,
+10
View File
@@ -139,6 +139,7 @@ export const AppContainer = (props: AppContainerProps) => {
);
const [isProcessing, setIsProcessing] = useState<boolean>(false);
const [embeddedShellFocused, setEmbeddedShellFocused] = useState(false);
const [showDebugProfiler, setShowDebugProfiler] = useState(false);
const [geminiMdFileCount, setGeminiMdFileCount] = useState<number>(
initializationResult.geminiMdFileCount,
@@ -175,6 +176,11 @@ export const AppContainer = (props: AppContainerProps) => {
[],
);
const toggleDebugProfiler = useCallback(
() => setShowDebugProfiler((prev) => !prev),
[],
);
// Helper to determine the effective model, considering the fallback state.
const getEffectiveModel = useCallback(() => {
if (config.isInFallbackMode()) {
@@ -460,6 +466,7 @@ Logging in with Google... Please restart Gemini CLI to continue.
},
setDebugMessage,
toggleCorgiMode: () => setCorgiMode((prev) => !prev),
toggleDebugProfiler,
dispatchExtensionStateUpdate,
addConfirmUpdateExtensionRequest,
}),
@@ -476,6 +483,7 @@ Logging in with Google... Please restart Gemini CLI to continue.
dispatchExtensionStateUpdate,
openPermissionsDialog,
addConfirmUpdateExtensionRequest,
toggleDebugProfiler,
],
);
@@ -1146,6 +1154,7 @@ Logging in with Google... Please restart Gemini CLI to continue.
extensionsUpdateState,
activePtyId,
embeddedShellFocused,
showDebugProfiler,
}),
[
isThemeDialogOpen,
@@ -1226,6 +1235,7 @@ Logging in with Google... Please restart Gemini CLI to continue.
activePtyId,
historyManager,
embeddedShellFocused,
showDebugProfiler,
],
);
+3 -3
View File
@@ -7,7 +7,7 @@
import type React from 'react';
import { useState, useEffect } from 'react';
import { Box, Text } from 'ink';
import Spinner from 'ink-spinner';
import { CliSpinner } from '../components/CliSpinner.js';
import { theme } from '../semantic-colors.js';
import { useKeypress } from '../hooks/useKeypress.js';
@@ -53,8 +53,8 @@ export function AuthInProgress({
) : (
<Box>
<Text>
<Spinner type="dots" /> Waiting for auth... (Press ESC or CTRL+C to
cancel)
<CliSpinner type="dots" /> Waiting for auth... (Press ESC or CTRL+C
to cancel)
</Text>
</Box>
)}
@@ -0,0 +1,24 @@
/**
* @license
* Copyright 2025 Google LLC
* SPDX-License-Identifier: Apache-2.0
*/
import { isDevelopment } from '../../utils/installationInfo.js';
import { CommandKind, type SlashCommand } from './types.js';
export const profileCommand: SlashCommand | null = isDevelopment
? {
name: 'profile',
kind: CommandKind.BUILT_IN,
description: 'Toggle the debug profile display',
action: async (context) => {
context.ui.toggleDebugProfiler();
return {
type: 'message',
messageType: 'info',
content: 'Toggled profile display.',
};
},
}
: null;
+1
View File
@@ -66,6 +66,7 @@ export interface CommandContext {
loadHistory: UseHistoryManagerReturn['loadHistory'];
/** Toggles a special display mode. */
toggleCorgiMode: () => void;
toggleDebugProfiler: () => void;
toggleVimEnabled: () => Promise<boolean>;
setGeminiMdFileCount: (count: number) => void;
reloadCommands: () => void;
@@ -0,0 +1,24 @@
/**
* @license
* Copyright 2025 Google LLC
* SPDX-License-Identifier: Apache-2.0
*/
import Spinner from 'ink-spinner';
import { type ComponentProps, useEffect } from 'react';
// A top-level field to track the total number of active spinners.
export let debugNumSpinners = 0;
export type SpinnerProps = ComponentProps<typeof Spinner>;
export const CliSpinner = (props: SpinnerProps) => {
useEffect(() => {
debugNumSpinners++;
return () => {
debugNumSpinners--;
};
}, []);
return <Spinner {...props} />;
};
@@ -0,0 +1,183 @@
/**
* @license
* Copyright 2025 Google LLC
* SPDX-License-Identifier: Apache-2.0
*/
import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest';
import {
profiler,
ACTION_TIMESTAMP_CAPACITY,
FRAME_TIMESTAMP_CAPACITY,
} from './DebugProfiler.js';
import { FixedDeque } from 'mnemonist';
describe('DebugProfiler', () => {
beforeEach(() => {
vi.useFakeTimers();
profiler.numFrames = 0;
profiler.totalIdleFrames = 0;
profiler.lastFrameStartTime = 0;
profiler.openedDebugConsole = false;
profiler.lastActionTimestamp = 0;
profiler.possiblyIdleFrameTimestamps = new FixedDeque<number>(
Array,
FRAME_TIMESTAMP_CAPACITY,
);
profiler.actionTimestamps = new FixedDeque<number>(
Array,
ACTION_TIMESTAMP_CAPACITY,
);
});
afterEach(() => {
vi.restoreAllMocks();
profiler.actionTimestamps.clear();
profiler.possiblyIdleFrameTimestamps.clear();
});
it('should not exceed action timestamp capacity', () => {
for (let i = 0; i < ACTION_TIMESTAMP_CAPACITY + 10; i++) {
profiler.reportAction();
// To ensure we don't trigger the debounce
profiler.lastActionTimestamp = 0;
}
expect(profiler.actionTimestamps.size).toBe(ACTION_TIMESTAMP_CAPACITY);
});
it('should not exceed frame timestamp capacity', () => {
for (let i = 0; i < FRAME_TIMESTAMP_CAPACITY + 10; i++) {
profiler.reportFrameRendered();
// To ensure we don't trigger the debounce
profiler.lastFrameStartTime = 0;
}
expect(profiler.possiblyIdleFrameTimestamps.size).toBe(
FRAME_TIMESTAMP_CAPACITY,
);
});
it('should drop oldest action timestamps when capacity is reached', () => {
for (let i = 0; i < ACTION_TIMESTAMP_CAPACITY; i++) {
profiler.actionTimestamps.push(i);
}
profiler.lastActionTimestamp = 0;
profiler.reportAction();
expect(profiler.actionTimestamps.size).toBe(ACTION_TIMESTAMP_CAPACITY);
expect(profiler.actionTimestamps.peekFirst()).toBe(1);
});
it('should drop oldest frame timestamps when capacity is reached', () => {
for (let i = 0; i < FRAME_TIMESTAMP_CAPACITY; i++) {
profiler.possiblyIdleFrameTimestamps.push(i);
}
profiler.lastFrameStartTime = 0;
profiler.reportFrameRendered();
expect(profiler.possiblyIdleFrameTimestamps.size).toBe(
FRAME_TIMESTAMP_CAPACITY,
);
expect(profiler.possiblyIdleFrameTimestamps.peekFirst()).toBe(1);
});
it('should not report frames as idle if an action happens shortly after', async () => {
const startTime = Date.now();
vi.setSystemTime(startTime);
for (let i = 0; i < 5; i++) {
profiler.reportFrameRendered();
vi.advanceTimersByTime(20);
}
vi.setSystemTime(startTime + 400);
profiler.reportAction();
vi.advanceTimersByTime(600);
profiler.checkForIdleFrames();
expect(profiler.totalIdleFrames).toBe(0);
});
it('should report frames as idle if no action happens nearby', async () => {
const startTime = Date.now();
vi.setSystemTime(startTime);
for (let i = 0; i < 5; i++) {
profiler.reportFrameRendered();
vi.advanceTimersByTime(20);
}
vi.advanceTimersByTime(1000);
profiler.checkForIdleFrames();
expect(profiler.totalIdleFrames).toBe(5);
});
it('should not report frames as idle if an action happens shortly before', async () => {
const startTime = Date.now();
vi.setSystemTime(startTime);
profiler.reportAction();
vi.advanceTimersByTime(400);
for (let i = 0; i < 5; i++) {
profiler.reportFrameRendered();
vi.advanceTimersByTime(20);
}
vi.advanceTimersByTime(600);
profiler.checkForIdleFrames();
expect(profiler.totalIdleFrames).toBe(0);
});
it('should correctly identify mixed idle and non-idle frames', async () => {
const startTime = Date.now();
vi.setSystemTime(startTime);
for (let i = 0; i < 3; i++) {
profiler.reportFrameRendered();
vi.advanceTimersByTime(20);
}
vi.advanceTimersByTime(1000);
profiler.reportAction();
vi.advanceTimersByTime(100);
for (let i = 0; i < 3; i++) {
profiler.reportFrameRendered();
vi.advanceTimersByTime(20);
}
vi.advanceTimersByTime(600);
profiler.checkForIdleFrames();
expect(profiler.totalIdleFrames).toBe(3);
});
it('should not report idle frames when actions are interleaved', async () => {
const startTime = Date.now();
vi.setSystemTime(startTime);
profiler.reportFrameRendered();
vi.advanceTimersByTime(20);
profiler.reportFrameRendered();
vi.advanceTimersByTime(200);
profiler.reportAction();
vi.advanceTimersByTime(200);
profiler.reportFrameRendered();
vi.advanceTimersByTime(20);
profiler.reportFrameRendered();
vi.advanceTimersByTime(600);
profiler.checkForIdleFrames();
expect(profiler.totalIdleFrames).toBe(0);
});
});
+177 -16
View File
@@ -5,32 +5,193 @@
*/
import { Text } from 'ink';
import { useEffect, useRef, useState } from 'react';
import { useEffect, useState } from 'react';
import { FixedDeque } from 'mnemonist';
import { theme } from '../semantic-colors.js';
import { useKeypress } from '../hooks/useKeypress.js';
import { useUIState } from '../contexts/UIStateContext.js';
import { debugNumSpinners } from './CliSpinner.js';
import { appEvents, AppEvent } from '../../utils/events.js';
// Frames that render at least this far before or after an action are considered
// idle frames.
const MIN_TIME_FROM_ACTION_TO_BE_IDLE = 500;
export const ACTION_TIMESTAMP_CAPACITY = 2048;
export const FRAME_TIMESTAMP_CAPACITY = 2048;
// Exported for testing purposes.
export const profiler = {
numFrames: 0,
totalIdleFrames: 0,
lastFrameStartTime: 0,
openedDebugConsole: false,
lastActionTimestamp: 0,
possiblyIdleFrameTimestamps: new FixedDeque<number>(
Array,
FRAME_TIMESTAMP_CAPACITY,
),
actionTimestamps: new FixedDeque<number>(Array, ACTION_TIMESTAMP_CAPACITY),
reportAction() {
const now = Date.now();
if (now - this.lastActionTimestamp > 16) {
if (this.actionTimestamps.size >= ACTION_TIMESTAMP_CAPACITY) {
this.actionTimestamps.shift();
}
this.actionTimestamps.push(now);
this.lastActionTimestamp = now;
}
},
reportFrameRendered() {
const now = Date.now();
// Simple frame detection logic (a write after at least 16ms is a new frame)
if (now - this.lastFrameStartTime > 16) {
this.lastFrameStartTime = now;
this.numFrames++;
if (debugNumSpinners === 0) {
if (this.possiblyIdleFrameTimestamps.size >= FRAME_TIMESTAMP_CAPACITY) {
this.possiblyIdleFrameTimestamps.shift();
}
this.possiblyIdleFrameTimestamps.push(now);
} else {
// If a spinner is present, consider this an action that both prevents
// this frame from being idle and also should prevent a follow on frame
// from being considered idle.
if (this.actionTimestamps.size >= ACTION_TIMESTAMP_CAPACITY) {
this.actionTimestamps.shift();
}
this.actionTimestamps.push(now);
}
}
},
checkForIdleFrames() {
const now = Date.now();
const judgementCutoff = now - MIN_TIME_FROM_ACTION_TO_BE_IDLE;
const oneSecondIntervalFromJudgementCutoff = judgementCutoff - 1000;
let idleInPastSecond = 0;
while (
this.possiblyIdleFrameTimestamps.size > 0 &&
this.possiblyIdleFrameTimestamps.peekFirst()! <= judgementCutoff
) {
const frameTime = this.possiblyIdleFrameTimestamps.shift()!;
const start = frameTime - MIN_TIME_FROM_ACTION_TO_BE_IDLE;
const end = frameTime + MIN_TIME_FROM_ACTION_TO_BE_IDLE;
while (
this.actionTimestamps.size > 0 &&
this.actionTimestamps.peekFirst()! < start
) {
this.actionTimestamps.shift();
}
const hasAction =
this.actionTimestamps.size > 0 &&
this.actionTimestamps.peekFirst()! <= end;
if (!hasAction) {
if (frameTime >= oneSecondIntervalFromJudgementCutoff) {
idleInPastSecond++;
}
this.totalIdleFrames++;
}
}
if (idleInPastSecond >= 5) {
if (this.openedDebugConsole === false) {
this.openedDebugConsole = true;
appEvents.emit(AppEvent.OpenDebugConsole);
}
appEvents.emit(
AppEvent.LogError,
`${idleInPastSecond} frames rendered while the app was ` +
`idle in the past second. This likely indicates severe infinite loop ` +
`React state management bugs.`,
);
}
},
};
export const DebugProfiler = () => {
const numRenders = useRef(0);
const [showNumRenders, setShowNumRenders] = useState(false);
const { showDebugProfiler } = useUIState();
const [forceRefresh, setForceRefresh] = useState(0);
// Effect for listening to stdin for keypresses and stdout for resize events.
useEffect(() => {
const stdin = process.stdin;
const stdout = process.stdout;
const handler = () => {
profiler.reportAction();
};
stdin.on('data', handler);
stdout.on('resize', handler);
return () => {
stdin.off('data', handler);
stdout.off('resize', handler);
};
}, []);
// Effect for patching stdout to count frames and detect idle ones
useEffect(() => {
const originalWrite = process.stdout.write;
const boundOriginalWrite = originalWrite.bind(process.stdout);
process.stdout.write = (
chunk: Uint8Array | string,
encodingOrCb?:
| BufferEncoding
| ((err?: NodeJS.ErrnoException | null) => void),
cb?: (err?: NodeJS.ErrnoException | null) => void,
) => {
profiler.reportFrameRendered();
if (typeof encodingOrCb === 'function') {
return boundOriginalWrite(chunk, encodingOrCb);
}
return boundOriginalWrite(chunk, encodingOrCb, cb);
};
return () => {
process.stdout.write = originalWrite;
};
}, []);
useEffect(() => {
numRenders.current++;
});
const updateInterval = setInterval(() => {
profiler.checkForIdleFrames();
}, 1000);
return () => clearInterval(updateInterval);
}, []);
useKeypress(
(key) => {
if (key.ctrl && key.name === 'b') {
setShowNumRenders((prev) => !prev);
}
},
{ isActive: true },
);
// Effect for updating stats
useEffect(() => {
if (!showDebugProfiler) {
return;
}
// Only update the UX infrequently as updating the UX itself will cause
// frames to run so can disturb what we are measuing.
const forceRefreshInterval = setInterval(() => {
setForceRefresh((f) => f + 1);
profiler.reportAction();
}, 4000);
return () => clearInterval(forceRefreshInterval);
}, [showDebugProfiler]);
if (!showNumRenders) {
if (!showDebugProfiler) {
return null;
}
return (
<Text color={theme.status.warning}>Renders: {numRenders.current} </Text>
<Text color={theme.status.warning} key={forceRefresh}>
Renders: {profiler.numFrames} (total),{' '}
<Text color={theme.status.error}>{profiler.totalIdleFrames} (idle) </Text>
</Text>
);
};
+5 -2
View File
@@ -18,6 +18,7 @@ import { DebugProfiler } from './DebugProfiler.js';
import { useTerminalSize } from '../hooks/useTerminalSize.js';
import { isNarrowWidth } from '../utils/isNarrowWidth.js';
import { isDevelopment } from '../../utils/installationInfo.js';
import { useUIState } from '../contexts/UIStateContext.js';
import { useConfig } from '../contexts/ConfigContext.js';
@@ -76,6 +77,8 @@ export const Footer: React.FC = () => {
const justifyContent = hideCWD && hideModelInfo ? 'center' : 'space-between';
const displayVimMode = vimEnabled ? vimMode : undefined;
const showDebugProfiler = debugMode || isDevelopment;
return (
<Box
justifyContent={justifyContent}
@@ -83,9 +86,9 @@ export const Footer: React.FC = () => {
flexDirection={isNarrow ? 'column' : 'row'}
alignItems={isNarrow ? 'flex-start' : 'center'}
>
{(debugMode || displayVimMode || !hideCWD) && (
{(showDebugProfiler || displayVimMode || !hideCWD) && (
<Box>
{debugMode && <DebugProfiler />}
{showDebugProfiler && <DebugProfiler />}
{displayVimMode && (
<Text color={theme.text.secondary}>[{displayVimMode}] </Text>
)}
@@ -6,7 +6,7 @@
import type React from 'react';
import { Text, useIsScreenReaderEnabled } from 'ink';
import Spinner from 'ink-spinner';
import { CliSpinner } from './CliSpinner.js';
import type { SpinnerName } from 'cli-spinners';
import { useStreamingContext } from '../contexts/StreamingContext.js';
import { StreamingState } from '../types.js';
@@ -61,7 +61,7 @@ export const GeminiSpinner: React.FC<GeminiSpinnerProps> = ({
<Text>{altText}</Text>
) : (
<Text color={theme.text.primary}>
<Spinner type={spinnerType} />
<CliSpinner type={spinnerType} />
</Text>
);
};
@@ -6,7 +6,7 @@
import { Box, Text } from 'ink';
import type { CompressionProps } from '../../types.js';
import Spinner from 'ink-spinner';
import { CliSpinner } from '../CliSpinner.js';
import { theme } from '../../semantic-colors.js';
import { SCREEN_READER_MODEL_PREFIX } from '../../textConstants.js';
import { CompressionStatus } from '@google/gemini-cli-core';
@@ -59,7 +59,7 @@ export function CompressionMessage({
<Box flexDirection="row">
<Box marginRight={1}>
{isPending ? (
<Spinner type="dots" />
<CliSpinner type="dots" />
) : (
<Text color={theme.text.accent}></Text>
)}
@@ -119,6 +119,7 @@ export interface UIState {
extensionsUpdateState: Map<string, ExtensionUpdateState>;
activePtyId: number | undefined;
embeddedShellFocused: boolean;
showDebugProfiler: boolean;
}
export const UIStateContext = createContext<UIState | null>(null);
@@ -51,6 +51,7 @@ interface SlashCommandProcessorActions {
quit: (messages: HistoryItem[]) => void;
setDebugMessage: (message: string) => void;
toggleCorgiMode: () => void;
toggleDebugProfiler: () => void;
dispatchExtensionStateUpdate: (action: ExtensionUpdateAction) => void;
addConfirmUpdateExtensionRequest: (request: ConfirmationRequest) => void;
}
@@ -197,6 +198,7 @@ export const useSlashCommandProcessor = (
pendingItem,
setPendingItem,
toggleCorgiMode: actions.toggleCorgiMode,
toggleDebugProfiler: actions.toggleDebugProfiler,
toggleVimEnabled,
setGeminiMdFileCount,
reloadCommands,
@@ -21,6 +21,7 @@ export function createNonInteractiveUI(): CommandContext['ui'] {
pendingItem: null,
setPendingItem: (_item) => {},
toggleCorgiMode: () => {},
toggleDebugProfiler: () => {},
toggleVimEnabled: async () => false,
setGeminiMdFileCount: (_count) => {},
reloadCommands: () => {},
@@ -8,6 +8,9 @@ import { isGitRepository } from '@google/gemini-cli-core';
import * as fs from 'node:fs';
import * as path from 'node:path';
import * as childProcess from 'node:child_process';
import process from 'node:process';
export const isDevelopment = process.env['NODE_ENV'] === 'development';
export enum PackageManager {
NPM = 'npm',