smashimo/oh-my-pi
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat(coding-agent): added subagent launch latency instrumentation

Browse Source 
- Add `onFirstChatDispatch` hook to `CreateAgentSessionOptions` to track the boundary between session creation and the initial model request.
- Update `runSubprocess` and `TaskTool` to measure and log detailed latency metrics across the subagent lifecycle, including semaphore queue wait, setup time, and dispatch latency.
This commit is contained in:
can1357
2026-06-19 16:06:17 +02:00
parent 30c2c35c88
commit 6bc194b0fb
3 changed files with 96 additions and 1 deletions
Download Patch File Download Diff File Expand all files Collapse all files
packages/coding-agent/src/task/executor.ts
+57
View File
@@ -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<SingleRes
onProgress,
} = options;
const startTime = Date.now();
// Set by the session's onFirstChatDispatch hook the first time the agent
// loop dispatches a chat request to the provider — the launch-complete boundary.
let firstChatDispatchAt: number | undefined;
// Check if already aborted
if (signal?.aborted) {
@@ -1868,6 +1881,14 @@ export async function runSubprocess(options: ExecutorOptions): Promise<SingleRes
abortSignal.removeEventListener("abort", onAbort);
}
};
// Launch-latency phase marks (performance.now()); read by the debug log
// emitted before this closure returns. Left undefined when setup throws
// before reaching the phase, which itself localizes the cost.
const perfStart = performance.now();
let resolvedAt: number | undefined;
let sessionOpenedAt: number | undefined;
let sessionCreatedAt: number | undefined;
let readyAt: number | undefined;
try {
checkAbort();
@@ -1935,6 +1956,7 @@ export async function runSubprocess(options: ExecutorOptions): Promise<SingleRes
const effectiveThinkingLevel = explicitThinkingLevel
? resolvedThinkingLevel
: (thinkingLevel ?? resolvedThinkingLevel);
resolvedAt = performance.now();
const effectiveCwd = worktree ?? cwd;
const sessionManager = sessionFile
@@ -1948,6 +1970,7 @@ export async function runSubprocess(options: ExecutorOptions): Promise<SingleRes
if (options.parentArtifactManager) {
sessionManager.adoptArtifactManager(options.parentArtifactManager);
}
sessionOpenedAt = performance.now();
const mcpProxyTools = options.mcpManager ? createMCPProxyTools(options.mcpManager) : [];
const enableMCP = !options.mcpManager;
@@ -2043,6 +2066,9 @@ export async function runSubprocess(options: ExecutorOptions): Promise<SingleRes
localProtocolOptions: options.localProtocolOptions,
telemetry: subagentTelemetry,
parentEvalSessionId: options.parentEvalSessionId,
onFirstChatDispatch: () => {
firstChatDispatchAt ??= performance.now();
},
});
const sessionPromise = createAgentSession(buildSubagentSessionOptions(sessionManager));
@@ -2056,6 +2082,7 @@ export async function runSubprocess(options: ExecutorOptions): Promise<SingleRes
void sessionPromise.then(created => 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<SingleRes
}
}
readyAt = performance.now();
const outcome = await driveSessionToYield(session, monitor, task);
exitCode = outcome.exitCode;
error = outcome.error;
@@ -2265,6 +2293,35 @@ export async function runSubprocess(options: ExecutorOptions): Promise<SingleRes
}
}
// Launch-latency breakdown (subagent invocation → first chat dispatch).
// Phase deltas are performance.now() spans; the semaphore brackets use the
// Date.now epochs captured by the spawn site (invokedAt before acquire,
// acquiredAt after) so queue wait and pre-run setup are reported apart.
const span = (from: number | undefined, to: number | undefined): number | undefined =>
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,
packages/coding-agent/src/task/index.ts
+15 -1
View File
@@ -798,6 +798,7 @@ export class TaskTool implements AgentTool<TaskToolSchemaInstance, TaskToolDetai
const startedAt = Date.now();
const semaphore = this.#getSpawnSemaphore();
await semaphore.acquire();
const acquiredAt = Date.now();
if (runSignal.aborted) {
semaphore.release();
progress.status = "aborted";
@@ -819,6 +820,7 @@ export class TaskTool implements AgentTool<TaskToolSchemaInstance, TaskToolDetai
agentId,
progress.index,
true,
{ invokedAt: startedAt, acquiredAt },
);
const finalText = result.content.find(part => part.type === "text")?.text ?? "(no output)";
const singleResult = result.details?.results[0];
@@ -900,7 +902,9 @@ export class TaskTool implements AgentTool<TaskToolSchemaInstance, TaskToolDetai
): Promise<AgentToolResult<TaskToolDetails>> {
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<TaskToolSchemaInstance, TaskToolDetai
onUpdate,
undefined,
0,
false,
{ invokedAt, acquiredAt },
);
} finally {
semaphore.release();
@@ -935,7 +941,9 @@ export class TaskTool implements AgentTool<TaskToolSchemaInstance, TaskToolDetai
spawnItems,
spawnItems.length,
async (item, index, workerSignal) => {
const invokedAt = Date.now();
await semaphore.acquire();
const acquiredAt = Date.now();
try {
const itemOnUpdate: AgentToolUpdateCallback<TaskToolDetails> | undefined = onUpdate
? update => {
@@ -953,6 +961,8 @@ export class TaskTool implements AgentTool<TaskToolSchemaInstance, TaskToolDetai
itemOnUpdate,
undefined,
index,
false,
{ invokedAt, acquiredAt },
);
} finally {
semaphore.release();
@@ -1012,8 +1022,9 @@ export class TaskTool implements AgentTool<TaskToolSchemaInstance, TaskToolDetai
preAllocatedId?: string,
spawnIndex = 0,
detached = false,
launchTiming?: { invokedAt: number; acquiredAt: number },
): Promise<AgentToolResult<TaskToolDetails>> {
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<TaskToolSchemaInstance, TaskToolDetai
preAllocatedId?: string,
spawnIndex = 0,
detached = false,
launchTiming?: { invokedAt: number; acquiredAt: number },
): Promise<AgentToolResult<TaskToolDetails>> {
const startTime = Date.now();
const { agents, projectAgentsDir } = await discoverAgents(this.session.cwd);
@@ -1265,6 +1277,8 @@ export class TaskTool implements AgentTool<TaskToolSchemaInstance, TaskToolDetai
detached,
id: agentId,
taskDepth,
invokedAt: launchTiming?.invokedAt,
acquiredAt: launchTiming?.acquiredAt,
modelOverride,
parentActiveModelPattern,
thinkingLevel: thinkingLevelOverride,