fix(agents): expose embedded preparation latency (#116936)

* fix(agents): attribute preparation latency

* test(agents): use tracked preparation temp dirs
This commit is contained in:
Vincent Koc
2026-08-01 01:14:01 +08:00
committed by GitHub
parent cd8a96491e
commit 749f5b2e27
4 changed files with 365 additions and 206 deletions
+29 -18
View File
@@ -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 });
+239 -188
View File
@@ -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<void> | 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<typeof guardSessionManager> | 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<void> | 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 } : {}),
@@ -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<string, unknown>);
}
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" },
]);
});
});
@@ -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<T>(
stage: string,
run: () => Promise<T> | T,
options: EmbeddedAgentPreparationTimingOptions = {},
): Promise<T> {
return measureDiagnosticsTimelineSpan("agent.prepare", run, timingOptions(stage, options));
}
/** Measures synchronous pre-provider work under the canonical agent preparation span. */
export function measureEmbeddedAgentPreparationSync<T>(
stage: string,
run: () => T,
options: EmbeddedAgentPreparationTimingOptions = {},
): T {
return measureDiagnosticsTimelineSpanSync("agent.prepare", run, timingOptions(stage, options));
}