diff --git a/src/agents/embedded-agent-runner/run-loop.ts b/src/agents/embedded-agent-runner/run-loop.ts index 0fad1fd86852..ea15c8da98ec 100644 --- a/src/agents/embedded-agent-runner/run-loop.ts +++ b/src/agents/embedded-agent-runner/run-loop.ts @@ -43,6 +43,7 @@ import { DEFAULT_EMPTY_RESPONSE_RETRY_LIMIT, DEFAULT_REASONING_ONLY_RETRY_LIMIT, } from "./run/incomplete-turn.js"; +import { measureEmbeddedAgentPreparation } from "./run/preparation-timing.js"; import { handleRetryLimitExhaustion } from "./run/retry-limit.js"; import { prepareEmbeddedRunRuntime } from "./run/runtime-preparation.js"; import { createEmbeddedRunSessionPromptState } from "./run/session-prompt-state.js"; @@ -77,20 +78,25 @@ export async function runPreparedEmbeddedLoop( const { maybeEmitFastModeAutoResetBestEffort, notifyExecutionPhase } = input.progressController; const { laneTaskAbortController } = input.laneController; let startupStagesEmitted = false; - const preparedRuntime = await prepareEmbeddedRunRuntime({ - runParams: params, - provider, - modelId, - agentDir, - workspaceDir: resolvedWorkspace, - globalLane, - hookRunner, - hookContext: hookCtx, - markStartupStage: (stage) => startupStages.mark(stage), - notifyExecutionPhase, - fallbackConfigured, - preparedModelRuntime: input.preparedModelRuntime, - }); + const preparedRuntime = await measureEmbeddedAgentPreparation( + "runtime", + () => + prepareEmbeddedRunRuntime({ + runParams: params, + provider, + modelId, + agentDir, + workspaceDir: resolvedWorkspace, + globalLane, + hookRunner, + hookContext: hookCtx, + markStartupStage: (stage) => startupStages.mark(stage), + notifyExecutionPhase, + fallbackConfigured, + preparedModelRuntime: input.preparedModelRuntime, + }), + { config: params.config }, + ); provider = preparedRuntime.provider; modelId = preparedRuntime.modelId; const { @@ -254,10 +260,15 @@ export async function runPreparedEmbeddedLoop( // Resolve the context engine once and reuse across retries to avoid // repeated initialization/connection overhead per attempt. ensureContextEnginesInitialized(); - const contextEngine = await resolveContextEngine(params.config, { - agentDir, - workspaceDir: resolvedWorkspace, - }); + const contextEngine = await measureEmbeddedAgentPreparation( + "context-engine", + () => + resolveContextEngine(params.config, { + agentDir, + workspaceDir: resolvedWorkspace, + }), + { config: params.config }, + ); const resolveContextEnginePluginId = () => resolveContextEngineOwnerPluginId(contextEngine); startupStages.mark("context-engine"); notifyExecutionPhase("context_engine", { provider, model: modelId }); diff --git a/src/agents/embedded-agent-runner/run/attempt.ts b/src/agents/embedded-agent-runner/run/attempt.ts index 96d512902376..f9094f6b4388 100644 --- a/src/agents/embedded-agent-runner/run/attempt.ts +++ b/src/agents/embedded-agent-runner/run/attempt.ts @@ -48,6 +48,10 @@ import { queueSessionsYieldInterruptMessage, SESSIONS_YIELD_ABORT_REASON, } from "./attempt.sessions-yield.js"; +import { + measureEmbeddedAgentPreparation, + measureEmbeddedAgentPreparationSync, +} from "./preparation-timing.js"; import { clearToolActivityRun } from "./tool-activity-heartbeat.js"; import type { EmbeddedRunAttemptParams, EmbeddedRunAttemptResult } from "./types.js"; @@ -72,7 +76,13 @@ export async function runEmbeddedAttempt( sandbox, sandboxSessionKey, sessionAgentId, - } = await prepareEmbeddedAttemptSetup(params); + } = await measureEmbeddedAgentPreparation( + "attempt.setup", + () => prepareEmbeddedAttemptSetup(params), + { + config: params.config, + }, + ); let restoreSkillEnv: (() => void) | undefined; const executionState: EmbeddedAttemptExecutionState = { @@ -147,12 +157,17 @@ export async function runEmbeddedAttempt( state: abortState, }); try { - const preparedSkills = prepareEmbeddedAttemptSkills({ - attempt: params, - effectiveWorkspace, - sandbox, - sessionAgentId, - }); + const preparedSkills = measureEmbeddedAgentPreparationSync( + "attempt.skills", + () => + prepareEmbeddedAttemptSkills({ + attempt: params, + effectiveWorkspace, + sandbox, + sessionAgentId, + }), + { config: params.config }, + ); restoreSkillEnv = preparedSkills.restoreSkillEnv; const { codeModeSkills, skillUsagePaths, skillsPrompt, skillsSnapshotForRun } = preparedSkills; prepStages.mark("skills"); @@ -178,35 +193,40 @@ export async function runEmbeddedAttempt( emitDiagnosticRunCompleted = emitCompleted; const corePluginToolStages = createEmbeddedRunStageTracker(); let toolSearchCatalogExecutor: ToolSearchCatalogToolExecutor | undefined; - const preparedToolBase = prepareEmbeddedAttemptToolBase({ - agentDir, - attempt: params, - effectiveCwd, - effectiveWorkspace, - markCoreToolStage: (name) => corePluginToolStages.mark(name), - onYield: (message) => { - yieldDetected = true; - yieldMessage = message; - queueYieldInterruptForSession?.(); - runAbortController.abort(SESSIONS_YIELD_ABORT_REASON); - abortSessionForYield?.(); - }, - resolvedWorkspace, - runAbortController, - runTrace, - sandbox, - sandboxSessionKey, - sessionAgentId, - skillUsagePaths, - skillsSnapshot: skillsSnapshotForRun, - codeModeSkills, - toolSearchCatalogExecutor: (toolParams) => { - if (!toolSearchCatalogExecutor) { - throw new Error("Tool Search catalog executor is unavailable for this run."); - } - return toolSearchCatalogExecutor(toolParams); - }, - }); + const preparedToolBase = measureEmbeddedAgentPreparationSync( + "attempt.tool-base", + () => + prepareEmbeddedAttemptToolBase({ + agentDir, + attempt: params, + effectiveCwd, + effectiveWorkspace, + markCoreToolStage: (name) => corePluginToolStages.mark(name), + onYield: (message) => { + yieldDetected = true; + yieldMessage = message; + queueYieldInterruptForSession?.(); + runAbortController.abort(SESSIONS_YIELD_ABORT_REASON); + abortSessionForYield?.(); + }, + resolvedWorkspace, + runAbortController, + runTrace, + sandbox, + sandboxSessionKey, + sessionAgentId, + skillUsagePaths, + skillsSnapshot: skillsSnapshotForRun, + codeModeSkills, + toolSearchCatalogExecutor: (toolParams) => { + if (!toolSearchCatalogExecutor) { + throw new Error("Tool Search catalog executor is unavailable for this run."); + } + return toolSearchCatalogExecutor(toolParams); + }, + }), + { config: params.config }, + ); toolSearchCatalogRef = preparedToolBase.toolSearchCatalogRef; const { codeModeControlsEnabledForRun, @@ -220,16 +240,21 @@ export async function runEmbeddedAttempt( } = preparedToolBase; prepStages.mark("core-plugin-tools"); emitCorePluginToolStageSummary("core-plugin-tools", corePluginToolStages.snapshot()); - const preparedBootstrap = await prepareEmbeddedAttemptBootstrap({ - attempt: params, - effectiveWorkspace, - hasReadTool: toolsEnabled && toolsRaw.some((tool) => tool.name === "read"), - isRawModelRun, - markStage: (name) => prepStages.mark(name), - resolvedWorkspace, - sessionAgentId, - sessionLabel: params.sessionKey ?? params.sessionId, - }); + const preparedBootstrap = await measureEmbeddedAgentPreparation( + "attempt.bootstrap", + () => + prepareEmbeddedAttemptBootstrap({ + attempt: params, + effectiveWorkspace, + hasReadTool: toolsEnabled && toolsRaw.some((tool) => tool.name === "read"), + isRawModelRun, + markStage: (name) => prepStages.mark(name), + resolvedWorkspace, + sessionAgentId, + sessionLabel: params.sessionKey ?? params.sessionId, + }), + { config: params.config }, + ); // Track sessions_yield tool invocation (callback pattern, like clientToolCallDetected) let yieldDetected = false; let yieldMessage: string | null = null; @@ -237,41 +262,51 @@ export async function runEmbeddedAttempt( let abortSessionForYield: (() => void) | null = null; let queueYieldInterruptForSession: (() => void) | null = null; let yieldAbortSettled: Promise | null = null; - const preparedBundleTools = await prepareEmbeddedAttemptBundleTools({ - agentDir, - attempt: params, - effectiveWorkspace, - getCurrentAttemptPluginMetadataSnapshot, - getProviderRuntimeHandle, - isRawModelRun, - preparedToolBase, - sessionAgentId, - }); + const preparedBundleTools = await measureEmbeddedAgentPreparation( + "attempt.bundle-tools", + () => + prepareEmbeddedAttemptBundleTools({ + agentDir, + attempt: params, + effectiveWorkspace, + getCurrentAttemptPluginMetadataSnapshot, + getProviderRuntimeHandle, + isRawModelRun, + preparedToolBase, + sessionAgentId, + }), + { config: params.config }, + ); bundleMcpRuntime = preparedBundleTools.bundleMcpRuntime; bundleLspRuntime = preparedBundleTools.bundleLspRuntime; const { clientTools, uncompactedEffectiveTools } = preparedBundleTools; // Catalog preparation registers global run state before tool projection and // diagnostics, so arm cleanup before either can fail and leak the catalog. toolSearchCatalogApplied = toolSearchCatalogRef !== undefined; - const preparedToolCatalog = prepareEmbeddedAttemptToolCatalog({ - attempt: params, - preparedToolBase, - bundleTools: { clientTools, uncompactedEffectiveTools }, - effectiveCwd, - effectiveWorkspace, - sessionAgentId, - sandboxSessionKey, - runTrace, - abortSignal: runAbortController.signal, - executeCodeModeTool: (toolParams) => { - if (!toolSearchCatalogExecutor) { - throw new Error("Code Mode catalog executor is unavailable for this run."); - } - return toolSearchCatalogExecutor(toolParams); - }, - getProviderRuntimeHandle, - markStage: (name) => prepStages.mark(name), - }); + const preparedToolCatalog = measureEmbeddedAgentPreparationSync( + "attempt.tool-catalog", + () => + prepareEmbeddedAttemptToolCatalog({ + attempt: params, + preparedToolBase, + bundleTools: { clientTools, uncompactedEffectiveTools }, + effectiveCwd, + effectiveWorkspace, + sessionAgentId, + sandboxSessionKey, + runTrace, + abortSignal: runAbortController.signal, + executeCodeModeTool: (toolParams) => { + if (!toolSearchCatalogExecutor) { + throw new Error("Code Mode catalog executor is unavailable for this run."); + } + return toolSearchCatalogExecutor(toolParams); + }, + getProviderRuntimeHandle, + markStage: (name) => prepStages.mark(name), + }), + { config: params.config }, + ); const { catalogToolHookContext, deferredDirectoryToolsCallable, @@ -280,46 +315,57 @@ export async function runEmbeddedAttempt( toolSearchRunPlan, } = preparedToolCatalog; toolSearchCatalogApplied = toolSearch.catalogRegistered; - const preparedSystemPrompt = await prepareEmbeddedAttemptSystemPrompt({ - activeContextEngine, - attempt: params, - bootstrap: preparedBootstrap, - capabilityToolNames: toolSearchRunPlan.capabilityToolNames, - defaultAgentId, - effectiveCwd, - effectiveTools, - effectiveWorkspace, - getProviderRuntimeHandle, - isRawModelRun, - markStage: (name) => prepStages.mark(name), - modelToolsEnabled: toolsEnabled, - proactiveSubagentOrchestration, - sandbox: sandbox ?? undefined, - sandboxSessionKey, - sessionAgentId, - skillsPrompt, - codeModeActive: codeModeControlsEnabledForRun, - toolSearchCatalogRef, - toolSearchDirectoryEnabled: toolSearchControlsEnabledForRun && toolSearch.catalogRegistered, - toolSearchRuntimeConfig, - }); + const preparedSystemPrompt = await measureEmbeddedAgentPreparation( + "attempt.system-prompt", + () => + prepareEmbeddedAttemptSystemPrompt({ + activeContextEngine, + attempt: params, + bootstrap: preparedBootstrap, + capabilityToolNames: toolSearchRunPlan.capabilityToolNames, + defaultAgentId, + effectiveCwd, + effectiveTools, + effectiveWorkspace, + getProviderRuntimeHandle, + isRawModelRun, + markStage: (name) => prepStages.mark(name), + modelToolsEnabled: toolsEnabled, + proactiveSubagentOrchestration, + sandbox: sandbox ?? undefined, + sandboxSessionKey, + sessionAgentId, + skillsPrompt, + codeModeActive: codeModeControlsEnabledForRun, + toolSearchCatalogRef, + toolSearchDirectoryEnabled: + toolSearchControlsEnabledForRun && toolSearch.catalogRegistered, + toolSearchRuntimeConfig, + }), + { config: params.config }, + ); let sessionManager: ReturnType | undefined; const { compactionTimeoutMs, ownedTranscriptWriteContext, sessionLockController, withOwnedSessionWriteLock, - } = await prepareEmbeddedAttemptSessionLock({ - attempt: params, - externalAbortController, - getSessionManager: () => sessionManager, - onSessionFileOwnerAcquired: (owner) => { - retainedSessionFileOwner = owner; - }, - onSessionLockReleaseReady: (release) => { - releaseRetainedSessionLock = release; - }, - }); + } = await measureEmbeddedAgentPreparation( + "attempt.session-lock", + () => + prepareEmbeddedAttemptSessionLock({ + attempt: params, + externalAbortController, + getSessionManager: () => sessionManager, + onSessionFileOwnerAcquired: (owner) => { + retainedSessionFileOwner = owner; + }, + onSessionLockReleaseReady: (release) => { + releaseRetainedSessionLock = release; + }, + }), + { config: params.config }, + ); let session: AgentSession | undefined; let removeToolResultContextGuard: (() => void) | undefined; @@ -328,85 +374,90 @@ export async function runEmbeddedAttempt( >["trajectoryRecorder"] = null; let buildAbortSettlePromise: () => Promise | null = () => null; try { - const preparedSessionRuntime = await prepareEmbeddedAttemptSessionRuntime({ - attempt: params, - ...(activeContextEngine ? { activeContextEngine } : {}), - agentDir, - effectiveCwd, - effectiveFsWorkspaceOnly, - effectiveWorkspace, - initialSystemPrompt: preparedSystemPrompt.systemPromptText, - isRawModelRun, - sessionManager: { - replayAllowedToolNames: toolSearchRunPlan.replayAllowedToolNames, - resolveActiveContextEnginePluginId, - sessionAgentId, - sessionLockController, - withOwnedSessionWriteLock, - }, - agentSession: { - agentCoreThinkingLevel, - clientToolPreparation: { - catalogToolHookContext, - clientTools, - codeModeControlsEnabledForRun, - deferredDirectoryToolsCallable, - effectiveTools, - replaySafetyOptions, - sandboxEnabled: Boolean(sandbox?.enabled), - sandboxSessionKey, - sessionAgentId, - toolSearchCatalogRef, - toolSearchRuntimeConfig, - uncompactedEffectiveTools, - }, - getCurrentAttemptPluginMetadataSnapshot, - markStage: (stage) => prepStages.mark(stage), - runAbortSignal: runAbortController.signal, - }, - contextGuards: { computerContextEpoch }, - trajectory: { - effectiveToolCount: effectiveTools.length, - localModelLeanEnabled, - ...(preparedSystemPrompt.systemPromptReport - ? { systemPromptReport: preparedSystemPrompt.systemPromptReport } - : {}), - }, - transport: { - abortSignal: runAbortController.signal, - codeModeControlsEnabled: codeModeControlsEnabledForRun, - getProviderRuntimeHandle, - providerThinkingLevel, - ...(sandbox !== undefined ? { sandbox } : {}), - sandboxSessionKey, - }, - externalAbortController, - lifecycle: { - onContextGuardsInstalled: (remove) => { - removeToolResultContextGuard = remove; - }, - onSessionCreated: (createdSession) => { - session = createdSession; - }, - onSessionManagerCreated: (createdSessionManager) => { - sessionManager = createdSessionManager; - }, - onSessionSettleTrackerReady: (build) => { - buildAbortSettlePromise = build; - }, - onSessionYieldReady: ({ abortActiveSession, activeSession }) => { - abortSessionForYield = () => { - yieldAbortSettled = abortActiveSession(SESSIONS_YIELD_ABORT_REASON); - }; - queueYieldInterruptForSession = () => { - queueSessionsYieldInterruptMessage(activeSession); - }; - }, - onTrajectoryRecorderCreated: (recorder) => { - trajectoryRecorder = recorder; - }, - }, - }); + const preparedSessionRuntime = await measureEmbeddedAgentPreparation( + "attempt.session-runtime", + () => + prepareEmbeddedAttemptSessionRuntime({ + attempt: params, + ...(activeContextEngine ? { activeContextEngine } : {}), + agentDir, + effectiveCwd, + effectiveFsWorkspaceOnly, + effectiveWorkspace, + initialSystemPrompt: preparedSystemPrompt.systemPromptText, + isRawModelRun, + sessionManager: { + replayAllowedToolNames: toolSearchRunPlan.replayAllowedToolNames, + resolveActiveContextEnginePluginId, + sessionAgentId, + sessionLockController, + withOwnedSessionWriteLock, + }, + agentSession: { + agentCoreThinkingLevel, + clientToolPreparation: { + catalogToolHookContext, + clientTools, + codeModeControlsEnabledForRun, + deferredDirectoryToolsCallable, + effectiveTools, + replaySafetyOptions, + sandboxEnabled: Boolean(sandbox?.enabled), + sandboxSessionKey, + sessionAgentId, + toolSearchCatalogRef, + toolSearchRuntimeConfig, + uncompactedEffectiveTools, + }, + getCurrentAttemptPluginMetadataSnapshot, + markStage: (stage) => prepStages.mark(stage), + runAbortSignal: runAbortController.signal, + }, + contextGuards: { computerContextEpoch }, + trajectory: { + effectiveToolCount: effectiveTools.length, + localModelLeanEnabled, + ...(preparedSystemPrompt.systemPromptReport + ? { systemPromptReport: preparedSystemPrompt.systemPromptReport } + : {}), + }, + transport: { + abortSignal: runAbortController.signal, + codeModeControlsEnabled: codeModeControlsEnabledForRun, + getProviderRuntimeHandle, + providerThinkingLevel, + ...(sandbox !== undefined ? { sandbox } : {}), + sandboxSessionKey, + }, + externalAbortController, + lifecycle: { + onContextGuardsInstalled: (remove) => { + removeToolResultContextGuard = remove; + }, + onSessionCreated: (createdSession) => { + session = createdSession; + }, + onSessionManagerCreated: (createdSessionManager) => { + sessionManager = createdSessionManager; + }, + onSessionSettleTrackerReady: (build) => { + buildAbortSettlePromise = build; + }, + onSessionYieldReady: ({ abortActiveSession, activeSession }) => { + abortSessionForYield = () => { + yieldAbortSettled = abortActiveSession(SESSIONS_YIELD_ABORT_REASON); + }; + queueYieldInterruptForSession = () => { + queueSessionsYieldInterruptMessage(activeSession); + }; + }, + onTrajectoryRecorderCreated: (recorder) => { + trajectoryRecorder = recorder; + }, + }, + }), + { config: params.config }, + ); const executionResult = await runEmbeddedAttemptExecutionPhase({ attempt: params, ...(activeContextEngine ? { activeContextEngine } : {}), diff --git a/src/agents/embedded-agent-runner/run/preparation-timing.test.ts b/src/agents/embedded-agent-runner/run/preparation-timing.test.ts new file mode 100644 index 000000000000..528149c5eab7 --- /dev/null +++ b/src/agents/embedded-agent-runner/run/preparation-timing.test.ts @@ -0,0 +1,60 @@ +import { readFile } from "node:fs/promises"; +import { join } from "node:path"; +import { afterEach, describe, expect, it } from "vitest"; +import { useAutoCleanupTempDirTracker } from "../../../../test/helpers/temp-dir.js"; +import { + measureEmbeddedAgentPreparation, + measureEmbeddedAgentPreparationSync, +} from "./preparation-timing.js"; + +const tempDirs = useAutoCleanupTempDirTracker(afterEach); + +async function createTimelineEnv() { + const dir = tempDirs.make("openclaw-agent-preparation-"); + return { + env: { + OPENCLAW_DIAGNOSTICS: "timeline", + OPENCLAW_DIAGNOSTICS_TIMELINE_PATH: join(dir, "timeline.jsonl"), + } as NodeJS.ProcessEnv, + path: join(dir, "timeline.jsonl"), + }; +} + +async function readTimeline(path: string) { + return (await readFile(path, "utf8")) + .trim() + .split("\n") + .map((line) => JSON.parse(line) as Record); +} + +describe("embedded agent preparation timing", () => { + it("emits the canonical span name with stage attribution", async () => { + const { env, path } = await createTimelineEnv(); + + await measureEmbeddedAgentPreparation("runtime", async () => "async", { env }); + expect(measureEmbeddedAgentPreparationSync("attempt.tool-base", () => "sync", { env })).toBe( + "sync", + ); + + const events = await readTimeline(path); + expect(events).toHaveLength(4); + expect(events.map((event) => event.name)).toEqual([ + "agent.prepare", + "agent.prepare", + "agent.prepare", + "agent.prepare", + ]); + expect(events.map((event) => event.phase)).toEqual([ + "agent.prepare", + "agent.prepare", + "agent.prepare", + "agent.prepare", + ]); + expect(events.map((event) => event.attributes)).toEqual([ + { stage: "runtime" }, + { stage: "runtime" }, + { stage: "attempt.tool-base" }, + { stage: "attempt.tool-base" }, + ]); + }); +}); diff --git a/src/agents/embedded-agent-runner/run/preparation-timing.ts b/src/agents/embedded-agent-runner/run/preparation-timing.ts new file mode 100644 index 000000000000..ca67c0798740 --- /dev/null +++ b/src/agents/embedded-agent-runner/run/preparation-timing.ts @@ -0,0 +1,37 @@ +import type { OpenClawConfig } from "../../../config/types.openclaw.js"; +import { + measureDiagnosticsTimelineSpan, + measureDiagnosticsTimelineSpanSync, +} from "../../../infra/diagnostics-timeline.js"; + +type EmbeddedAgentPreparationTimingOptions = { + config?: OpenClawConfig; + env?: NodeJS.ProcessEnv; +}; + +function timingOptions(stage: string, options: EmbeddedAgentPreparationTimingOptions) { + return { + config: options.config, + env: options.env, + phase: "agent.prepare", + attributes: { stage }, + }; +} + +/** Measures async pre-provider work under the canonical agent preparation span. */ +export function measureEmbeddedAgentPreparation( + stage: string, + run: () => Promise | T, + options: EmbeddedAgentPreparationTimingOptions = {}, +): Promise { + return measureDiagnosticsTimelineSpan("agent.prepare", run, timingOptions(stage, options)); +} + +/** Measures synchronous pre-provider work under the canonical agent preparation span. */ +export function measureEmbeddedAgentPreparationSync( + stage: string, + run: () => T, + options: EmbeddedAgentPreparationTimingOptions = {}, +): T { + return measureDiagnosticsTimelineSpanSync("agent.prepare", run, timingOptions(stage, options)); +}