diff --git a/packages/core/src/config/config.test.ts b/packages/core/src/config/config.test.ts index d4a9197124..bb4123d0db 100644 --- a/packages/core/src/config/config.test.ts +++ b/packages/core/src/config/config.test.ts @@ -34,7 +34,10 @@ import { ShellTool } from '../tools/shell.js'; import { ReadFileTool } from '../tools/read-file.js'; import { GrepTool } from '../tools/grep.js'; import { RipGrepTool, canUseRipgrep } from '../tools/ripGrep.js'; -import { logRipgrepFallback } from '../telemetry/loggers.js'; +import { + logRipgrepFallback, + logApprovalModeDuration, +} from '../telemetry/loggers.js'; import { RipgrepFallbackEvent } from '../telemetry/types.js'; import { ToolRegistry } from '../tools/tool-registry.js'; import { ACTIVATE_SKILL_TOOL_NAME } from '../tools/tool-names.js'; @@ -131,6 +134,7 @@ vi.mock('../telemetry/loggers.js', async (importOriginal) => { return { ...actual, logRipgrepFallback: vi.fn(), + logApprovalModeDuration: vi.fn(), }; }); @@ -1419,6 +1423,84 @@ describe('setApprovalMode with folder trust', () => { expect(updateSpy).not.toHaveBeenCalled(); }); + describe('approval mode duration logging', () => { + beforeEach(() => { + vi.mocked(logApprovalModeDuration).mockClear(); + }); + + it('should initialize lastModeSwitchTime with performance.now() and log positive duration', () => { + const startTime = 1000; + const endTime = 5000; + const performanceSpy = vi.spyOn(performance, 'now'); + + performanceSpy.mockReturnValueOnce(startTime); + const config = new Config(baseParams); + vi.spyOn(config, 'isTrustedFolder').mockReturnValue(true); + + performanceSpy.mockReturnValueOnce(endTime); + config.setApprovalMode(ApprovalMode.PLAN); + + expect(logApprovalModeDuration).toHaveBeenCalledWith( + config, + expect.objectContaining({ + mode: ApprovalMode.DEFAULT, + duration_ms: endTime - startTime, + }), + ); + performanceSpy.mockRestore(); + }); + + it('should skip logging if duration is zero or negative', () => { + const startTime = 5000; + const endTime = 4000; + const performanceSpy = vi.spyOn(performance, 'now'); + + performanceSpy.mockReturnValueOnce(startTime); + const config = new Config(baseParams); + vi.spyOn(config, 'isTrustedFolder').mockReturnValue(true); + + performanceSpy.mockReturnValueOnce(endTime); + config.setApprovalMode(ApprovalMode.PLAN); + + expect(logApprovalModeDuration).not.toHaveBeenCalled(); + performanceSpy.mockRestore(); + }); + + it('should update lastModeSwitchTime after logging to prevent double counting', () => { + const time1 = 1000; + const time2 = 3000; + const time3 = 6000; + const performanceSpy = vi.spyOn(performance, 'now'); + + performanceSpy.mockReturnValueOnce(time1); + const config = new Config(baseParams); + vi.spyOn(config, 'isTrustedFolder').mockReturnValue(true); + + performanceSpy.mockReturnValueOnce(time2); + config.setApprovalMode(ApprovalMode.PLAN); + expect(logApprovalModeDuration).toHaveBeenCalledWith( + config, + expect.objectContaining({ + mode: ApprovalMode.DEFAULT, + duration_ms: time2 - time1, + }), + ); + + vi.mocked(logApprovalModeDuration).mockClear(); + + performanceSpy.mockReturnValueOnce(time3); + config.setApprovalMode(ApprovalMode.YOLO); + expect(logApprovalModeDuration).toHaveBeenCalledWith( + config, + expect.objectContaining({ + mode: ApprovalMode.PLAN, + duration_ms: time3 - time2, + }), + ); + performanceSpy.mockRestore(); + }); + }); + describe('registerCoreTools', () => { beforeEach(() => { vi.clearAllMocks(); diff --git a/packages/core/src/config/config.ts b/packages/core/src/config/config.ts index 2b80ea13f0..4836e77fc8 100644 --- a/packages/core/src/config/config.ts +++ b/packages/core/src/config/config.ts @@ -699,7 +699,7 @@ export class Config { private terminalBackground: string | undefined = undefined; private remoteAdminSettings: AdminControlsSettings | undefined; private latestApiRequest: GenerateContentParameters | undefined; - private lastModeSwitchTime: number = Date.now(); + private lastModeSwitchTime: number = performance.now(); readonly userHintService: UserHintService; private approvedPlanPath: string | undefined; @@ -1798,12 +1798,11 @@ export class Config { const currentMode = this.getApprovalMode(); if (currentMode !== mode) { - this.logCurrentModeDuration(this.getApprovalMode()); + this.logCurrentModeDuration(currentMode); logApprovalModeSwitch( this, new ApprovalModeSwitchEvent(currentMode, mode), ); - this.lastModeSwitchTime = Date.now(); } this.policyEngine.setApprovalMode(mode); @@ -1866,12 +1865,15 @@ export class Config { * Logs the duration of the current approval mode. */ logCurrentModeDuration(mode: ApprovalMode): void { - const now = Date.now(); + const now = performance.now(); const duration = now - this.lastModeSwitchTime; - logApprovalModeDuration( - this, - new ApprovalModeDurationEvent(mode, duration), - ); + if (duration > 0) { + logApprovalModeDuration( + this, + new ApprovalModeDurationEvent(mode, duration), + ); + } + this.lastModeSwitchTime = now; } isYoloModeDisabled(): boolean {