diff --git a/packages/coding-agent/src/sdk.ts b/packages/coding-agent/src/sdk.ts index aa5ee2949..22e6eec5d 100644 --- a/packages/coding-agent/src/sdk.ts +++ b/packages/coding-agent/src/sdk.ts @@ -533,6 +533,16 @@ export interface CreateAgentSessionOptions { */ telemetry?: AgentTelemetryConfig; + /** + * Fired once, when the agent loop hands its first request to the provider + * transport (i.e. the `streamFn` wrapper is first invoked). Used to measure + * subagent launch latency — the boundary between "session built" and "model + * call dispatched". This is the loop's dispatch point, slightly before the + * actual provider HTTP call (per-request prep, identical across all + * requests, follows it), which is the right granularity for launch timing. + */ + onFirstChatDispatch?: () => void; + /** Whether to auto-approve all tool calls (--auto-approve CLI flag). Default: false */ autoApprove?: boolean; } @@ -2398,6 +2408,9 @@ export async function createAgentSession(options: CreateAgentSessionOptions = {} ? undefined : serviceTierSetting; + // One-shot launch-latency marker: fired the first time the loop dispatches + // a chat request to the provider transport. See onFirstChatDispatch. + let notifyFirstChatDispatch = options.onFirstChatDispatch; agent = new Agent({ initialState: { systemPrompt, @@ -2431,6 +2444,17 @@ export async function createAgentSession(options: CreateAgentSessionOptions = {} getToolContext: tc => toolContextStore.getContext(tc), getApiKey: requestModel => modelRegistry.resolver(requestModel, agent.sessionId), streamFn: (streamModel, context, streamOptions) => { + if (notifyFirstChatDispatch) { + const cb = notifyFirstChatDispatch; + notifyFirstChatDispatch = undefined; + try { + cb(); + } catch (err) { + logger.warn("onFirstChatDispatch hook threw", { + error: err instanceof Error ? err.message : String(err), + }); + } + } const openrouterRoutingPreset = settings.get("providers.openrouterVariant"); const openrouterVariant = openrouterRoutingPreset && openrouterRoutingPreset !== "default" ? openrouterRoutingPreset : undefined; diff --git a/packages/coding-agent/src/task/executor.ts b/packages/coding-agent/src/task/executor.ts index 514973193..8dc2eb1ae 100644 --- a/packages/coding-agent/src/task/executor.ts +++ b/packages/coding-agent/src/task/executor.ts @@ -302,6 +302,16 @@ export interface ExecutorOptions { enableLsp?: boolean; signal?: AbortSignal; onProgress?: (progress: AgentProgress) => void; + /** + * Epochs (ms, `Date.now()`) bracketing the concurrency-semaphore wait: + * `invokedAt` is stamped at the spawn boundary before `acquire()`, + * `acquiredAt` immediately after. {@link runSubprocess} reports true queue + * wait (`acquiredAt - invokedAt`) and pre-run setup (`startTime - acquiredAt`) + * separately in the launch-timing debug log. Undefined for callers that + * bypass the semaphore path. + */ + invokedAt?: number; + acquiredAt?: number; sessionFile?: string | null; persistArtifacts?: boolean; artifactsDir?: string; @@ -1698,6 +1708,9 @@ export async function runSubprocess(options: ExecutorOptions): Promise { + firstChatDispatchAt ??= performance.now(); + }, }); const sessionPromise = createAgentSession(buildSubagentSessionOptions(sessionManager)); @@ -2056,6 +2082,7 @@ export async function runSubprocess(options: ExecutorOptions): Promise created.session.dispose()).catch(() => {}); throw err; } + sessionCreatedAt = performance.now(); monitor.setActiveSession(session); installRegistryStatusSync(session); @@ -2201,6 +2228,7 @@ export async function runSubprocess(options: ExecutorOptions): Promise + from !== undefined && to !== undefined ? Math.round(to - from) : undefined; + const queueMs = + options.invokedAt !== undefined && options.acquiredAt !== undefined + ? Math.round(options.acquiredAt - options.invokedAt) + : undefined; + const preRunMs = options.acquiredAt !== undefined ? Math.round(startTime - options.acquiredAt) : undefined; + const setupToFirstChatMs = span(perfStart, firstChatDispatchAt); + const invokeToFirstChatMs = + options.invokedAt !== undefined && setupToFirstChatMs !== undefined + ? Math.round(startTime - options.invokedAt) + setupToFirstChatMs + : undefined; + logger.debug("subagent launch timing", { + id, + agent: agent.name, + queueMs, + preRunMs, + resolveMs: span(perfStart, resolvedAt), + sessionOpenMs: span(resolvedAt, sessionOpenedAt), + createSessionMs: span(sessionOpenedAt, sessionCreatedAt), + readyMs: span(sessionCreatedAt, readyAt), + promptToFirstChatMs: span(readyAt, firstChatDispatchAt), + setupToFirstChatMs, + invokeToFirstChatMs, + }); return { exitCode, error, diff --git a/packages/coding-agent/src/task/index.ts b/packages/coding-agent/src/task/index.ts index 3367800ba..7530c9dce 100644 --- a/packages/coding-agent/src/task/index.ts +++ b/packages/coding-agent/src/task/index.ts @@ -798,6 +798,7 @@ export class TaskTool implements AgentTool part.type === "text")?.text ?? "(no output)"; const singleResult = result.details?.results[0]; @@ -900,7 +902,9 @@ export class TaskTool implements AgentTool> { const semaphore = this.#getSpawnSemaphore(); if (spawnItems.length === 1) { + const invokedAt = Date.now(); await semaphore.acquire(); + const acquiredAt = Date.now(); try { return await this.#executeSync( toolCallId, @@ -909,6 +913,8 @@ export class TaskTool implements AgentTool { + const invokedAt = Date.now(); await semaphore.acquire(); + const acquiredAt = Date.now(); try { const itemOnUpdate: AgentToolUpdateCallback | undefined = onUpdate ? update => { @@ -953,6 +961,8 @@ export class TaskTool implements AgentTool> { - return this.#runSpawn(toolCallId, params, signal, onUpdate, preAllocatedId, spawnIndex, detached); + return this.#runSpawn(toolCallId, params, signal, onUpdate, preAllocatedId, spawnIndex, detached, launchTiming); } /** Spawn a fresh subagent and run it to completion. */ @@ -1025,6 +1036,7 @@ export class TaskTool implements AgentTool> { const startTime = Date.now(); const { agents, projectAgentsDir } = await discoverAgents(this.session.cwd); @@ -1265,6 +1277,8 @@ export class TaskTool implements AgentTool