diff --git a/agents/cursor.ts b/agents/cursor.ts index 6cf14f5..f10f29d 100644 --- a/agents/cursor.ts +++ b/agents/cursor.ts @@ -5,6 +5,7 @@ import { spawn } from "node:child_process"; import { existsSync, mkdirSync, readFileSync, writeFileSync } from "node:fs"; import { homedir } from "node:os"; import { join } from "node:path"; +import { performance } from "node:perf_hooks"; import type { Effort } from "../external.ts"; import { ghPullfrogMcpName } from "../external.ts"; import { markActivity } from "../utils/activity.ts"; @@ -249,7 +250,7 @@ export const cursor = agent({ log.info("» running Cursor CLI..."); - const startTime = Date.now(); + const startTime = performance.now(); // create env without XDG_CONFIG_HOME so CLI uses $HOME/.cursor/ where we wrote config const cliEnv = Object.fromEntries( @@ -307,7 +308,7 @@ export const cursor = agent({ log.warning(`Cursor CLI terminated by signal: ${signal}`); } - const duration = ((Date.now() - startTime) / 1000).toFixed(1); + const duration = ((performance.now() - startTime) / 1000).toFixed(1); if (code === 0) { log.success(`Cursor CLI completed successfully in ${duration}s`); @@ -327,7 +328,7 @@ export const cursor = agent({ }); child.on("error", (error) => { - const duration = ((Date.now() - startTime) / 1000).toFixed(1); + const duration = ((performance.now() - startTime) / 1000).toFixed(1); const errorMessage = error.message || String(error); log.error(`Cursor CLI execution failed after ${duration}s: ${errorMessage}`); resolve({ diff --git a/agents/opencode.ts b/agents/opencode.ts index 336aa10..f0a25b0 100644 --- a/agents/opencode.ts +++ b/agents/opencode.ts @@ -3,6 +3,7 @@ // changes to web search configuration should be reflected in wiki/websearch.md import { mkdirSync, writeFileSync } from "node:fs"; import { join } from "node:path"; +import { performance } from "node:perf_hooks"; import { ghPullfrogMcpName } from "../external.ts"; import { getIdleMs, markActivity } from "../utils/activity.ts"; import { log } from "../utils/cli.ts"; @@ -93,7 +94,7 @@ export const opencode = agent({ log.debug(`» HOME: ${env.HOME}`); log.debug(`» XDG_CONFIG_HOME: ${env.XDG_CONFIG_HOME}`); - const startTime = Date.now(); + const startTime = performance.now(); let eventCount = 0; const thinkingTimer = new ThinkingTimer(); @@ -190,8 +191,10 @@ export const opencode = agent({ }, }); - const duration = Date.now() - startTime; - log.info(`» OpenCode CLI completed in ${duration}ms with exit code ${result.exitCode}`); + const duration = performance.now() - startTime; + log.info( + `» OpenCode CLI completed in ${Math.round(duration)}ms with exit code ${result.exitCode}` + ); // if zero events processed, something went wrong - surface stderr context if (eventCount === 0) { @@ -243,7 +246,7 @@ export const opencode = agent({ }; } catch (error) { // activity timeout or process timeout - surface the real cause - const duration = Date.now() - startTime; + const duration = performance.now() - startTime; const errorMessage = error instanceof Error ? error.message : String(error); const isActivityTimeout = errorMessage.includes("activity timeout"); @@ -583,11 +586,11 @@ const messageHandlers = { if (toolId) { const toolStartTime = toolCallTimings.get(toolId); if (toolStartTime) { - const toolDuration = Date.now() - toolStartTime; + const toolDuration = performance.now() - toolStartTime; toolCallTimings.delete(toolId); const stepContext = currentStepId ? ` (step=${currentStepType || "unknown"})` : ""; log.debug( - `» OpenCode tool_result${stepContext}: id=${toolId}, status=${status}, duration=${toolDuration}ms` + `» OpenCode tool_result${stepContext}: id=${toolId}, status=${status}, duration=${Math.round(toolDuration)}ms` ); if (output) { log.debug(` output: ${typeof output === "string" ? output : JSON.stringify(output)}`); diff --git a/entry b/entry index 98e13cd..7b72755 100755 --- a/entry +++ b/entry @@ -3682,7 +3682,7 @@ var require_util2 = __commonJS({ "use strict"; var { redirectStatusSet, referrerPolicySet: referrerPolicyTokens, badPortsSet } = require_constants2(); var { getGlobalOrigin } = require_global(); - var { performance: performance2 } = __require("perf_hooks"); + var { performance: performance8 } = __require("perf_hooks"); var { isBlobLike, toUSVString, ReadableStreamFrom } = require_util(); var assert3 = __require("assert"); var { isUint8Array } = __require("util/types"); @@ -3845,7 +3845,7 @@ var require_util2 = __commonJS({ } } function coarsenedSharedCurrentTime(crossOriginIsolatedCapability) { - return performance2.now(); + return performance8.now(); } function createOpaqueTimingInfo(timingInfo) { return { @@ -48701,7 +48701,7 @@ var require_util11 = __commonJS({ var { redirectStatusSet, referrerPolicyTokens, badPortsSet } = require_constants8(); var { getGlobalOrigin } = require_global3(); var { collectASequenceOfCodePoints, collectAnHTTPQuotedString, removeChars, parseMIMEType } = require_data_url(); - var { performance: performance2 } = __require("node:perf_hooks"); + var { performance: performance8 } = __require("node:perf_hooks"); var { ReadableStreamFrom, isValidHTTPToken, normalizedMethodRecordsBase } = require_util10(); var assert3 = __require("node:assert"); var { isUint8Array } = __require("node:util/types"); @@ -48855,7 +48855,7 @@ var require_util11 = __commonJS({ }; } function coarsenedSharedCurrentTime(crossOriginIsolatedCapability) { - return coarsenTime(performance2.now(), crossOriginIsolatedCapability); + return coarsenTime(performance8.now(), crossOriginIsolatedCapability); } function createOpaqueTimingInfo(timingInfo) { return { @@ -140533,16 +140533,18 @@ var LIFECYCLE_HOOK_TIMEOUT_MS = 12e4; // utils/subprocess.ts import { spawn as nodeSpawn } from "node:child_process"; +import { performance as performance3 } from "node:perf_hooks"; // utils/activity.ts +import { performance as performance2 } from "node:perf_hooks"; var DEFAULT_ACTIVITY_TIMEOUT_MS = 6e4; var DEFAULT_ACTIVITY_CHECK_INTERVAL_MS = 5e3; -var _lastActivity = Date.now(); +var _lastActivity = performance2.now(); function markActivity() { - _lastActivity = Date.now(); + _lastActivity = performance2.now(); } function getIdleMs() { - return Date.now() - _lastActivity; + return Math.round(performance2.now() - _lastActivity); } function wrapWrite(original, onActivity) { const wrapped = (chunk, encodingOrCb, cb) => { @@ -140649,7 +140651,7 @@ async function spawn2(options) { const { cmd, args: args2, env: env2, input, timeout, cwd, stdio, onStdout, onStderr } = options; const activityTimeoutMs = options.activityTimeout ?? DEFAULT_ACTIVITY_TIMEOUT_MS; installSignalHandlers(); - const startTime = Date.now(); + const startTime = performance3.now(); let stdoutBuffer = ""; let stderrBuffer = ""; return new Promise((resolve3, reject) => { @@ -140666,7 +140668,7 @@ async function spawn2(options) { let activityCheckIntervalId; let isTimedOut = false; let isActivityTimedOut = false; - let lastActivityTime = Date.now(); + let lastActivityTime = performance3.now(); if (timeout) { timeoutId = setTimeout(() => { isTimedOut = true; @@ -140680,7 +140682,7 @@ async function spawn2(options) { } if (activityTimeoutMs > 0) { activityCheckIntervalId = setInterval(() => { - const idleMs = Date.now() - lastActivityTime; + const idleMs = performance3.now() - lastActivityTime; if (idleMs > activityTimeoutMs) { isActivityTimedOut = true; const idleSec = Math.round(idleMs / 1e3); @@ -140691,7 +140693,7 @@ async function spawn2(options) { }, DEFAULT_ACTIVITY_CHECK_INTERVAL_MS); } function updateActivity() { - lastActivityTime = Date.now(); + lastActivityTime = performance3.now(); } if (child.stdout) { child.stdout.on("data", (data) => { @@ -140710,7 +140712,7 @@ async function spawn2(options) { }); } child.on("close", (exitCode) => { - const durationMs = Date.now() - startTime; + const durationMs = performance3.now() - startTime; untrackChild(child); if (timeoutId) clearTimeout(timeoutId); if (activityCheckIntervalId) clearInterval(activityCheckIntervalId); @@ -140719,7 +140721,7 @@ async function spawn2(options) { return; } if (isActivityTimedOut) { - const idleSec = Math.round((Date.now() - lastActivityTime) / 1e3); + const idleSec = Math.round((performance3.now() - lastActivityTime) / 1e3); reject(new Error(`activity timeout: no output for ${idleSec}s`)); return; } @@ -140731,7 +140733,7 @@ async function spawn2(options) { }); }); child.on("error", (error49) => { - const durationMs = Date.now() - startTime; + const durationMs = performance3.now() - startTime; untrackChild(child); if (timeoutId) clearTimeout(timeoutId); if (activityCheckIntervalId) clearInterval(activityCheckIntervalId); @@ -141539,6 +141541,9 @@ function CommitInfoTool(ctx) { }); } +// prep/index.ts +import { performance as performance4 } from "node:perf_hooks"; + // prep/installNodeDependencies.ts import { existsSync as existsSync2, readFileSync as readFileSync2 } from "node:fs"; import { join as join5 } from "node:path"; @@ -142121,7 +142126,7 @@ var installPythonDependencies = { var prepSteps = [installNodeDependencies, installPythonDependencies]; async function runPrepPhase(options) { log.debug("\xBB starting prep phase..."); - const startTime = Date.now(); + const startTime = performance4.now(); const results = []; for (const step of prepSteps) { const shouldRun = await step.shouldRun(); @@ -142138,8 +142143,8 @@ async function runPrepPhase(options) { log.warning(`\xBB ${step.name}: ${result.issues[0]}`); } } - const totalDurationMs = Date.now() - startTime; - log.debug(`\xBB prep phase completed (${totalDurationMs}ms)`); + const totalDurationMs = performance4.now() - startTime; + log.debug(`\xBB prep phase completed (${Math.round(totalDurationMs)}ms)`); return results; } @@ -144306,14 +144311,15 @@ async function installFromCurl(params) { } // utils/timer.ts +import { performance as performance5 } from "node:perf_hooks"; var Timer = class { initialTimestamp; lastCheckpointTimestamp = null; constructor() { - this.initialTimestamp = Date.now(); + this.initialTimestamp = performance5.now(); } checkpoint(name) { - const now = Date.now(); + const now = performance5.now(); const duration4 = this.lastCheckpointTimestamp ? now - this.lastCheckpointTimestamp : now - this.initialTimestamp; log.debug(`\xBB ${name}: ${duration4}ms`); this.lastCheckpointTimestamp = now; @@ -144330,11 +144336,11 @@ var ThinkingTimer = class { }); lastToolResultTimestamp = null; markToolResult() { - this.lastToolResultTimestamp = Date.now(); + this.lastToolResultTimestamp = performance5.now(); log.debug(`\xBB thinking timer: markToolResult at ${this.lastToolResultTimestamp}`); } markToolCall() { - const now = Date.now(); + const now = performance5.now(); log.debug( `\xBB thinking timer: markToolCall at ${now}, lastToolResult=${this.lastToolResultTimestamp}` ); @@ -144872,6 +144878,7 @@ import { spawn as spawn3 } from "node:child_process"; import { existsSync as existsSync6, mkdirSync as mkdirSync5, readFileSync as readFileSync5, writeFileSync as writeFileSync9 } from "node:fs"; import { homedir } from "node:os"; import { join as join11 } from "node:path"; +import { performance as performance6 } from "node:perf_hooks"; var cursorEffortModels = { mini: null, // use default (auto) @@ -144991,7 +144998,7 @@ var cursor = agent({ } const cursorArgs = [...baseArgs, "--force", ctx.instructions.full]; log.info("\xBB running Cursor CLI..."); - const startTime = Date.now(); + const startTime = performance6.now(); const cliEnv = Object.fromEntries( Object.entries(process.env).filter(([key]) => key !== "XDG_CONFIG_HOME") ); @@ -145033,7 +145040,7 @@ var cursor = agent({ if (signal) { log.warning(`Cursor CLI terminated by signal: ${signal}`); } - const duration4 = ((Date.now() - startTime) / 1e3).toFixed(1); + const duration4 = ((performance6.now() - startTime) / 1e3).toFixed(1); if (code === 0) { log.success(`Cursor CLI completed successfully in ${duration4}s`); resolve3({ @@ -145051,7 +145058,7 @@ var cursor = agent({ } }); child.on("error", (error49) => { - const duration4 = ((Date.now() - startTime) / 1e3).toFixed(1); + const duration4 = ((performance6.now() - startTime) / 1e3).toFixed(1); const errorMessage = error49.message || String(error49); log.error(`Cursor CLI execution failed after ${duration4}s: ${errorMessage}`); resolve3({ @@ -145370,6 +145377,7 @@ function configureGeminiSettings(ctx) { // agents/opencode.ts import { mkdirSync as mkdirSync7, writeFileSync as writeFileSync11 } from "node:fs"; import { join as join13 } from "node:path"; +import { performance as performance7 } from "node:perf_hooks"; var PROVIDER_ERROR_PATTERNS = [ { pattern: "429", label: "rate limited (429)" }, { pattern: "RESOURCE_EXHAUSTED", label: "quota exhausted" }, @@ -145424,7 +145432,7 @@ var opencode = agent({ log.debug(`\xBB working directory: ${repoDir}`); log.debug(`\xBB HOME: ${env2.HOME}`); log.debug(`\xBB XDG_CONFIG_HOME: ${env2.XDG_CONFIG_HOME}`); - const startTime = Date.now(); + const startTime = performance7.now(); let eventCount = 0; const thinkingTimer = new ThinkingTimer(); const recentStderr = []; @@ -145497,8 +145505,10 @@ var opencode = agent({ } } }); - const duration4 = Date.now() - startTime; - log.info(`\xBB OpenCode CLI completed in ${duration4}ms with exit code ${result.exitCode}`); + const duration4 = performance7.now() - startTime; + log.info( + `\xBB OpenCode CLI completed in ${Math.round(duration4)}ms with exit code ${result.exitCode}` + ); if (eventCount === 0) { const stderrContext = recentStderr.join("\n"); const diagnosis = lastProviderError ? `provider error: ${lastProviderError}` : "unknown cause (no stdout events received)"; @@ -145538,7 +145548,7 @@ ${stderrContext}`); output: finalOutput || output }; } catch (error49) { - const duration4 = Date.now() - startTime; + const duration4 = performance7.now() - startTime; const errorMessage = error49 instanceof Error ? error49.message : String(error49); const isActivityTimeout = errorMessage.includes("activity timeout"); const stderrContext = recentStderr.slice(-10).join("\n"); @@ -145693,11 +145703,11 @@ var messageHandlers4 = { if (toolId) { const toolStartTime = toolCallTimings.get(toolId); if (toolStartTime) { - const toolDuration = Date.now() - toolStartTime; + const toolDuration = performance7.now() - toolStartTime; toolCallTimings.delete(toolId); const stepContext = currentStepId ? ` (step=${currentStepType || "unknown"})` : ""; log.debug( - `\xBB OpenCode tool_result${stepContext}: id=${toolId}, status=${status}, duration=${toolDuration}ms` + `\xBB OpenCode tool_result${stepContext}: id=${toolId}, status=${status}, duration=${Math.round(toolDuration)}ms` ); if (output) { log.debug(` output: ${typeof output === "string" ? output : JSON.stringify(output)}`); diff --git a/prep/index.ts b/prep/index.ts index bdb7c03..ec81942 100644 --- a/prep/index.ts +++ b/prep/index.ts @@ -1,3 +1,4 @@ +import { performance } from "node:perf_hooks"; import { log } from "../utils/cli.ts"; import { installNodeDependencies } from "./installNodeDependencies.ts"; import { installPythonDependencies } from "./installPythonDependencies.ts"; @@ -14,7 +15,7 @@ const prepSteps: PrepDefinition[] = [installNodeDependencies, installPythonDepen */ export async function runPrepPhase(options: PrepOptions): Promise { log.debug("» starting prep phase..."); - const startTime = Date.now(); + const startTime = performance.now(); const results: PrepResult[] = []; for (const step of prepSteps) { @@ -35,8 +36,8 @@ export async function runPrepPhase(options: PrepOptions): Promise } } - const totalDurationMs = Date.now() - startTime; - log.debug(`» prep phase completed (${totalDurationMs}ms)`); + const totalDurationMs = performance.now() - startTime; + log.debug(`» prep phase completed (${Math.round(totalDurationMs)}ms)`); return results; } diff --git a/utils/activity.ts b/utils/activity.ts index 00219a1..2e96c09 100644 --- a/utils/activity.ts +++ b/utils/activity.ts @@ -1,3 +1,5 @@ +import { performance } from "node:perf_hooks"; + export const DEFAULT_ACTIVITY_TIMEOUT_MS = 60_000; export const DEFAULT_ACTIVITY_CHECK_INTERVAL_MS = 5_000; @@ -28,21 +30,21 @@ type WriteFunction = { }; // module-level activity tracking - allows agents to mark activity on any event -let _lastActivity = Date.now(); +let _lastActivity = performance.now(); /** * mark activity to reset the no-output timeout. * call this whenever the agent emits any event, even if it isn't logged to stdout. */ export function markActivity(): void { - _lastActivity = Date.now(); + _lastActivity = performance.now(); } /** * get the time since last activity in milliseconds */ export function getIdleMs(): number { - return Date.now() - _lastActivity; + return Math.round(performance.now() - _lastActivity); } function wrapWrite(original: WriteFunction, onActivity: () => void): WriteFunction { diff --git a/utils/subprocess.ts b/utils/subprocess.ts index 5d7446e..6be0df4 100644 --- a/utils/subprocess.ts +++ b/utils/subprocess.ts @@ -1,4 +1,5 @@ import { type ChildProcess, spawn as nodeSpawn } from "node:child_process"; +import { performance } from "node:perf_hooks"; import { DEFAULT_ACTIVITY_CHECK_INTERVAL_MS, DEFAULT_ACTIVITY_TIMEOUT_MS } from "./activity.ts"; import { log } from "./cli.ts"; @@ -107,7 +108,7 @@ export async function spawn(options: SpawnOptions): Promise { installSignalHandlers(); - const startTime = Date.now(); + const startTime = performance.now(); let stdoutBuffer = ""; let stderrBuffer = ""; @@ -129,7 +130,7 @@ export async function spawn(options: SpawnOptions): Promise { let activityCheckIntervalId: NodeJS.Timeout | undefined; let isTimedOut = false; let isActivityTimedOut = false; - let lastActivityTime = Date.now(); + let lastActivityTime = performance.now(); // overall timeout if (timeout) { @@ -148,7 +149,7 @@ export async function spawn(options: SpawnOptions): Promise { // activity timeout: kill if no output for too long if (activityTimeoutMs > 0) { activityCheckIntervalId = setInterval(() => { - const idleMs = Date.now() - lastActivityTime; + const idleMs = performance.now() - lastActivityTime; if (idleMs > activityTimeoutMs) { isActivityTimedOut = true; const idleSec = Math.round(idleMs / 1000); @@ -160,7 +161,7 @@ export async function spawn(options: SpawnOptions): Promise { } function updateActivity(): void { - lastActivityTime = Date.now(); + lastActivityTime = performance.now(); } if (child.stdout) { @@ -182,7 +183,7 @@ export async function spawn(options: SpawnOptions): Promise { } child.on("close", (exitCode) => { - const durationMs = Date.now() - startTime; + const durationMs = performance.now() - startTime; untrackChild(child); if (timeoutId) clearTimeout(timeoutId); @@ -194,7 +195,7 @@ export async function spawn(options: SpawnOptions): Promise { } if (isActivityTimedOut) { - const idleSec = Math.round((Date.now() - lastActivityTime) / 1000); + const idleSec = Math.round((performance.now() - lastActivityTime) / 1000); reject(new Error(`activity timeout: no output for ${idleSec}s`)); return; } @@ -208,7 +209,7 @@ export async function spawn(options: SpawnOptions): Promise { }); child.on("error", (error) => { - const durationMs = Date.now() - startTime; + const durationMs = performance.now() - startTime; untrackChild(child); if (timeoutId) clearTimeout(timeoutId); diff --git a/utils/timer.test.ts b/utils/timer.test.ts index 42a1ec2..f8519a7 100644 --- a/utils/timer.test.ts +++ b/utils/timer.test.ts @@ -1,22 +1,22 @@ +import { performance } from "node:perf_hooks"; import * as cli from "./cli.ts"; import { ThinkingTimer, Timer } from "./timer.ts"; describe("Timer", () => { beforeEach(() => { vi.spyOn(cli.log, "debug"); - // Mock Date.now to have predictable timestamps - vi.useFakeTimers(); + // Mock performance.now() to have predictable timestamps + vi.spyOn(performance, "now"); }); afterEach(() => { vi.restoreAllMocks(); - vi.useRealTimers(); }); describe("constructor", () => { it("should initialize with current timestamp", () => { const mockTime = 1000000; - vi.setSystemTime(mockTime); + vi.mocked(performance.now).mockReturnValueOnce(mockTime).mockReturnValueOnce(mockTime); const timer = new Timer(); timer.checkpoint("test"); @@ -28,11 +28,12 @@ describe("Timer", () => { describe("checkpoint", () => { it("should log duration from initial timestamp on first checkpoint", () => { const startTime = 1000000; - vi.setSystemTime(startTime); - const timer = new Timer(); - const checkpointTime = startTime + 100; - vi.setSystemTime(checkpointTime); + vi.mocked(performance.now) + .mockReturnValueOnce(startTime) // constructor + .mockReturnValueOnce(checkpointTime); // checkpoint + + const timer = new Timer(); timer.checkpoint("first"); expect(cli.log.debug).toHaveBeenCalledWith("» first: 100ms"); @@ -40,17 +41,15 @@ describe("Timer", () => { it("should log duration from last checkpoint on subsequent checkpoints", () => { const startTime = 1000000; - vi.setSystemTime(startTime); - const timer = new Timer(); - - // First checkpoint const firstCheckpointTime = startTime + 50; - vi.setSystemTime(firstCheckpointTime); - timer.checkpoint("first"); - - // Second checkpoint const secondCheckpointTime = firstCheckpointTime + 75; - vi.setSystemTime(secondCheckpointTime); + vi.mocked(performance.now) + .mockReturnValueOnce(startTime) // constructor + .mockReturnValueOnce(firstCheckpointTime) // first checkpoint + .mockReturnValueOnce(secondCheckpointTime); // second checkpoint + + const timer = new Timer(); + timer.checkpoint("first"); timer.checkpoint("second"); expect(cli.log.debug).toHaveBeenCalledTimes(2); @@ -60,19 +59,15 @@ describe("Timer", () => { it("should handle multiple checkpoints correctly", () => { const startTime = 1000000; - vi.setSystemTime(startTime); + vi.mocked(performance.now) + .mockReturnValueOnce(startTime) // constructor + .mockReturnValueOnce(startTime + 10) // step1 + .mockReturnValueOnce(startTime + 25) // step2 + .mockReturnValueOnce(startTime + 45); // step3 + const timer = new Timer(); - - // First checkpoint - vi.setSystemTime(startTime + 10); timer.checkpoint("step1"); - - // Second checkpoint - vi.setSystemTime(startTime + 25); timer.checkpoint("step2"); - - // Third checkpoint - vi.setSystemTime(startTime + 45); timer.checkpoint("step3"); expect(cli.log.debug).toHaveBeenCalledTimes(3); @@ -83,10 +78,11 @@ describe("Timer", () => { it("should handle zero duration correctly", () => { const startTime = 1000000; - vi.setSystemTime(startTime); - const timer = new Timer(); + vi.mocked(performance.now) + .mockReturnValueOnce(startTime) // constructor + .mockReturnValueOnce(startTime); // checkpoint - // Checkpoint immediately + const timer = new Timer(); timer.checkpoint("immediate"); expect(cli.log.debug).toHaveBeenCalledWith("» immediate: 0ms"); @@ -94,10 +90,11 @@ describe("Timer", () => { it("should handle custom checkpoint names", () => { const startTime = 1000000; - vi.setSystemTime(startTime); - const timer = new Timer(); + vi.mocked(performance.now) + .mockReturnValueOnce(startTime) // constructor + .mockReturnValueOnce(startTime + 200); // checkpoint - vi.setSystemTime(startTime + 200); + const timer = new Timer(); timer.checkpoint("Custom Checkpoint Name"); expect(cli.log.debug).toHaveBeenCalledWith("» Custom Checkpoint Name: 200ms"); @@ -108,23 +105,22 @@ describe("Timer", () => { describe("ThinkingTimer", () => { beforeEach(() => { vi.spyOn(cli.log, "info"); - vi.useFakeTimers(); + vi.spyOn(performance, "now"); }); afterEach(() => { vi.restoreAllMocks(); - vi.useRealTimers(); }); describe("markToolResult", () => { it("should store the current timestamp", () => { const startTime = 1000000; - vi.setSystemTime(startTime); + vi.mocked(performance.now) + .mockReturnValueOnce(startTime) // markToolResult + .mockReturnValueOnce(startTime + 5000); // markToolCall const timer = new ThinkingTimer(); timer.markToolResult(); - - vi.setSystemTime(startTime + 5000); timer.markToolCall(); expect(cli.log.info).toHaveBeenCalled(); @@ -141,12 +137,12 @@ describe("ThinkingTimer", () => { it("should not log if elapsed time is below threshold (3000ms)", () => { const startTime = 1000000; - vi.setSystemTime(startTime); + vi.mocked(performance.now) + .mockReturnValueOnce(startTime) // markToolResult + .mockReturnValueOnce(startTime + 2999); // markToolCall const timer = new ThinkingTimer(); timer.markToolResult(); - - vi.setSystemTime(startTime + 2999); timer.markToolCall(); expect(cli.log.info).not.toHaveBeenCalled(); @@ -154,12 +150,12 @@ describe("ThinkingTimer", () => { it("should log if elapsed time equals threshold (3000ms)", () => { const startTime = 1000000; - vi.setSystemTime(startTime); + vi.mocked(performance.now) + .mockReturnValueOnce(startTime) // markToolResult + .mockReturnValueOnce(startTime + 3000); // markToolCall const timer = new ThinkingTimer(); timer.markToolResult(); - - vi.setSystemTime(startTime + 3000); timer.markToolCall(); expect(cli.log.info).toHaveBeenCalledWith("» thought for 3 seconds"); @@ -167,12 +163,12 @@ describe("ThinkingTimer", () => { it("should log if elapsed time exceeds threshold", () => { const startTime = 1000000; - vi.setSystemTime(startTime); + vi.mocked(performance.now) + .mockReturnValueOnce(startTime) // markToolResult + .mockReturnValueOnce(startTime + 5500); // markToolCall const timer = new ThinkingTimer(); timer.markToolResult(); - - vi.setSystemTime(startTime + 5500); timer.markToolCall(); expect(cli.log.info).toHaveBeenCalledWith("» thought for 5.5 seconds"); @@ -180,12 +176,12 @@ describe("ThinkingTimer", () => { it("should format large durations correctly", () => { const startTime = 1000000; - vi.setSystemTime(startTime); + vi.mocked(performance.now) + .mockReturnValueOnce(startTime) // markToolResult + .mockReturnValueOnce(startTime + 15000); // markToolCall const timer = new ThinkingTimer(); timer.markToolResult(); - - vi.setSystemTime(startTime + 15000); timer.markToolCall(); expect(cli.log.info).toHaveBeenCalledWith("» thought for 15 seconds"); @@ -193,15 +189,14 @@ describe("ThinkingTimer", () => { it("should handle multiple markToolCall invocations", () => { const startTime = 1000000; - vi.setSystemTime(startTime); + vi.mocked(performance.now) + .mockReturnValueOnce(startTime) // markToolResult + .mockReturnValueOnce(startTime + 4000) // first markToolCall + .mockReturnValueOnce(startTime + 5000); // second markToolCall const timer = new ThinkingTimer(); timer.markToolResult(); - - vi.setSystemTime(startTime + 4000); timer.markToolCall(); - - vi.setSystemTime(startTime + 5000); timer.markToolCall(); expect(cli.log.info).toHaveBeenCalledTimes(2); diff --git a/utils/timer.ts b/utils/timer.ts index bd6db5b..c13e96b 100644 --- a/utils/timer.ts +++ b/utils/timer.ts @@ -1,3 +1,4 @@ +import { performance } from "node:perf_hooks"; import { log } from "./cli.ts"; export class Timer { @@ -5,11 +6,11 @@ export class Timer { private lastCheckpointTimestamp: number | null = null; constructor() { - this.initialTimestamp = Date.now(); + this.initialTimestamp = performance.now(); } checkpoint(name: string): void { - const now = Date.now(); + const now = performance.now(); const duration = this.lastCheckpointTimestamp ? now - this.lastCheckpointTimestamp : now - this.initialTimestamp; @@ -33,12 +34,12 @@ export class ThinkingTimer { private lastToolResultTimestamp: number | null = null; markToolResult(): void { - this.lastToolResultTimestamp = Date.now(); + this.lastToolResultTimestamp = performance.now(); log.debug(`» thinking timer: markToolResult at ${this.lastToolResultTimestamp}`); } markToolCall(): void { - const now = Date.now(); + const now = performance.now(); log.debug( `» thinking timer: markToolCall at ${now}, lastToolResult=${this.lastToolResultTimestamp}` );