From b3f522f9d904836973a34d39b89a6aabd789d788 Mon Sep 17 00:00:00 2001 From: Priyanshu Choudhary <57816400+Priyanchew@users.noreply.github.com> Date: Tue, 5 May 2026 22:14:31 +0530 Subject: [PATCH] chore(perf): add AO_PERF-gated instrumentation for dashboard load Temporary tracing added to diagnose 15-20s dashboard terminal load on Mac and Windows. Gated on AO_PERF=1 (server) and NEXT_PUBLIC_AO_PERF=1 (client) so production paths stay untouched. To be removed once the bottleneck is fixed. Wrap points: - core/perf.ts: perfMark / perfTime helpers + perfCid - web /api/sessions/[id]: per-stage timings (getServices, sm.get, audit, enrichMetadata, total) - core/session-manager: runtime.isAlive, agent.getActivityState, agent.getSessionInfo, ensureHandleAndEnrich - agent-codex: findCodexSessionFile (scanned/opened/matched counts) + cache hit marker - runtime-process/pty-client: connect outcome + isAlive (split connectMs vs statusMs) - web/lib/serialize: enrich legs (agentSummary vs issueTitle) timed independently while still running concurrently - web/sessions/[id]/page.tsx: client.fetch.start/end with cid header forwarded for end-to-end correlation - web/MuxProvider: ws.open + ws.firstByte per terminal --- packages/core/src/index.ts | 3 + packages/core/src/perf.ts | 56 +++++++++++++++++++ packages/core/src/session-manager.ts | 32 +++++++---- packages/plugins/agent-codex/src/index.ts | 23 +++++++- .../plugins/runtime-process/src/pty-client.ts | 13 +++++ .../web/src/app/api/sessions/[id]/route.ts | 23 +++++--- packages/web/src/app/sessions/[id]/page.tsx | 23 +++++++- packages/web/src/lib/serialize.ts | 18 +++++- packages/web/src/providers/MuxProvider.tsx | 12 ++++ 9 files changed, 183 insertions(+), 20 deletions(-) create mode 100644 packages/core/src/perf.ts diff --git a/packages/core/src/index.ts b/packages/core/src/index.ts index 158b73707..a0d104e78 100644 --- a/packages/core/src/index.ts +++ b/packages/core/src/index.ts @@ -8,6 +8,9 @@ // Types — everything plugins and consumers need export * from "./types.js"; +// Perf tracing — temporary, AO_PERF=1 gated +export { PERF_ON, perfMark, perfTime, perfTimeSync, perfCid } from "./perf.js"; + // Config — YAML loader + validation export { loadConfig, diff --git a/packages/core/src/perf.ts b/packages/core/src/perf.ts new file mode 100644 index 000000000..98e9d6f48 --- /dev/null +++ b/packages/core/src/perf.ts @@ -0,0 +1,56 @@ +/** + * Lightweight perf tracing, gated on AO_PERF=1. + * + * Temporary diagnostic — added to trace dashboard load slowness across + * client → API → session-manager → plugins. Remove once the bottleneck is + * fixed. Greppable by `[ao-perf]`. + */ + +export const PERF_ON = process.env.AO_PERF === "1"; + +export function perfMark( + cid: string, + stage: string, + ms: number, + extra?: Record, +): void { + if (!PERF_ON) return; + const tail = extra ? " " + JSON.stringify(extra) : ""; + // eslint-disable-next-line no-console + console.log(`[ao-perf] cid=${cid} ${stage}=${ms}ms${tail}`); +} + +export async function perfTime( + cid: string, + stage: string, + fn: () => Promise, + extra?: Record, +): Promise { + if (!PERF_ON) return fn(); + const t = Date.now(); + try { + return await fn(); + } finally { + perfMark(cid, stage, Date.now() - t, extra); + } +} + +export function perfTimeSync( + cid: string, + stage: string, + fn: () => T, + extra?: Record, +): T { + if (!PERF_ON) return fn(); + const t = Date.now(); + try { + return fn(); + } finally { + perfMark(cid, stage, Date.now() - t, extra); + } +} + +/** Random 6-char correlation id, used when caller didn't supply one. */ +export function perfCid(): string { + return Math.random().toString(36).slice(2, 8); +} diff --git a/packages/core/src/session-manager.ts b/packages/core/src/session-manager.ts index 02087bcfd..a0b7617f1 100644 --- a/packages/core/src/session-manager.ts +++ b/packages/core/src/session-manager.ts @@ -50,6 +50,7 @@ import { type CanonicalSessionLifecycle, PR_STATE, } from "./types.js"; +import { perfTime } from "./perf.js"; import { readMetadataRaw, writeMetadata, @@ -1025,7 +1026,10 @@ export function createSessionManager(deps: SessionManagerDeps): OpenCodeSessionM session.status !== "spawning" ) { try { - const alive = await plugins.runtime.isAlive(session.runtimeHandle); + const alive = await perfTime(`sm:${session.id}`, "sm.runtime.isAlive", () => + plugins.runtime!.isAlive(session.runtimeHandle!), + { runtime: session.runtimeHandle.runtimeName }, + ); if (!alive) { session.lifecycle.runtime.state = "missing"; session.lifecycle.runtime.reason = @@ -1068,7 +1072,10 @@ export function createSessionManager(deps: SessionManagerDeps): OpenCodeSessionM session.activitySignal = createActivitySignal("unavailable"); if (plugins.agent) { try { - const detected = await plugins.agent.getActivityState(session, config.readyThresholdMs); + const detected = await perfTime(`sm:${session.id}`, "sm.agent.getActivityState", () => + plugins.agent!.getActivityState(session, config.readyThresholdMs), + { agent: session.agent ?? "unknown" }, + ); if (detected !== null) { session.activitySignal = classifyActivitySignal(detected, "native"); session.activity = detected.state; @@ -1088,7 +1095,10 @@ export function createSessionManager(deps: SessionManagerDeps): OpenCodeSessionM // Enrich with live agent session info (summary, cost). let info: Awaited>; try { - info = await plugins.agent.getSessionInfo(session); + info = await perfTime(`sm:${session.id}`, "sm.agent.getSessionInfo", () => + plugins.agent!.getSessionInfo(session), + { agent: session.agent ?? "unknown" }, + ); } catch { // Can't get session info — keep existing values info = null; @@ -2063,13 +2073,15 @@ export function createSessionManager(deps: SessionManagerDeps): OpenCodeSessionM const selection = resolveSelectionForSession(project, sessionId, repaired.raw); const effectiveAgentName = selection.agentName; const plugins = resolvePlugins(project, effectiveAgentName); - await ensureHandleAndEnrich( - session, - sessionId, - sessionsDir, - project, - effectiveAgentName, - plugins, + await perfTime(`sm:${sessionId}`, "sm.ensureHandleAndEnrich", () => + ensureHandleAndEnrich( + session, + sessionId, + sessionsDir, + project, + effectiveAgentName, + plugins, + ), ); return session; diff --git a/packages/plugins/agent-codex/src/index.ts b/packages/plugins/agent-codex/src/index.ts index ad84e1f58..de4388053 100644 --- a/packages/plugins/agent-codex/src/index.ts +++ b/packages/plugins/agent-codex/src/index.ts @@ -9,6 +9,7 @@ import { getActivityFallbackState, recordTerminalActivity, isWindows, + perfMark, type Agent, type AgentSessionInfo, type AgentLaunchConfig, @@ -228,14 +229,26 @@ async function sessionFileMatchesCwd(filePath: string, workspacePath: string): P * Returns the path to the most recently modified matching file, or null. */ async function findCodexSessionFile(workspacePath: string): Promise { + const t0 = Date.now(); const jsonlFiles = await collectJsonlFiles(CODEX_SESSIONS_DIR); - if (jsonlFiles.length === 0) return null; + const collectMs = Date.now() - t0; + if (jsonlFiles.length === 0) { + perfMark(`codex:${workspacePath}`, "codex.findSessionFile", Date.now() - t0, { + scanned: 0, + matched: 0, + }); + return null; + } let bestMatch: { path: string; mtime: number } | null = null; + let openedFiles = 0; + let matchedFiles = 0; for (const filePath of jsonlFiles) { + openedFiles++; const matches = await sessionFileMatchesCwd(filePath, workspacePath); if (matches) { + matchedFiles++; try { const s = await stat(filePath); if (!bestMatch || s.mtimeMs > bestMatch.mtime) { @@ -247,6 +260,13 @@ async function findCodexSessionFile(workspacePath: string): Promise { const cached = sessionFileCache.get(workspacePath); if (cached && Date.now() < cached.expiry) { + perfMark(`codex:${workspacePath}`, "codex.findSessionFile.cache", 0, { hit: 1 }); return cached.path; } const result = await findCodexSessionFile(workspacePath); diff --git a/packages/plugins/runtime-process/src/pty-client.ts b/packages/plugins/runtime-process/src/pty-client.ts index 2a5fe8958..23c5228d7 100644 --- a/packages/plugins/runtime-process/src/pty-client.ts +++ b/packages/plugins/runtime-process/src/pty-client.ts @@ -9,6 +9,7 @@ */ import { connect, type Socket } from "node:net"; +import { perfMark } from "@aoagents/ao-core"; import { MSG_TERMINAL_INPUT, MSG_TERMINAL_DATA, @@ -60,6 +61,7 @@ export function getPipePath(sessionId: string): string { export function connectPtyHost(pipePath: string, timeoutMs = 3000): Promise { return new Promise((resolve, reject) => { let settled = false; + const t0 = Date.now(); const sock = connect(pipePath); @@ -67,6 +69,7 @@ export function connectPtyHost(pipePath: string, timeoutMs = 3000): Promise { + const t0 = Date.now(); let sock: Socket; try { sock = await connectPtyHost(pipePath, 2000); } catch { + perfMark(`pty:${pipePath}`, "pty.isAlive", Date.now() - t0, { outcome: "connect_fail" }); return false; } + const tConnected = Date.now(); return new Promise((resolve) => { let settled = false; @@ -233,6 +241,11 @@ export async function ptyHostIsAlive(pipePath: string): Promise { settled = true; clearTimeout(timer); sock.destroy(); + perfMark(`pty:${pipePath}`, "pty.isAlive", Date.now() - t0, { + outcome: result ? "alive" : "dead", + connectMs: tConnected - t0, + statusMs: Date.now() - tConnected, + }); resolve(result); }; diff --git a/packages/web/src/app/api/sessions/[id]/route.ts b/packages/web/src/app/api/sessions/[id]/route.ts index db0ce8128..84e8cfa95 100644 --- a/packages/web/src/app/api/sessions/[id]/route.ts +++ b/packages/web/src/app/api/sessions/[id]/route.ts @@ -1,5 +1,10 @@ import { type NextRequest } from "next/server"; -import { getProjectSessionsDir, readAgentReportAuditTrailAsync } from "@aoagents/ao-core"; +import { + getProjectSessionsDir, + readAgentReportAuditTrailAsync, + perfMark, + perfTime, +} from "@aoagents/ao-core"; import { getServices } from "@/lib/services"; import { sessionToDashboard, @@ -18,10 +23,11 @@ export async function GET(_request: NextRequest, { params }: { params: Promise<{ const startedAt = Date.now(); try { const { id } = await params; - const { config, registry, sessionManager } = await getServices(); + const { config, registry, sessionManager } = await perfTime(correlationId, "server.getServices", () => getServices()); - const coreSession = await sessionManager.get(id); + const coreSession = await perfTime(correlationId, "server.sm.get", () => sessionManager.get(id), { id }); if (!coreSession) { + perfMark(correlationId, "server.total", Date.now() - startedAt, { outcome: "404" }); return jsonWithCorrelation({ error: "Session not found" }, { status: 404 }, correlationId); } @@ -32,19 +38,22 @@ export async function GET(_request: NextRequest, { params }: { params: Promise<{ const auditPromise = readAgentReportAuditTrailAsync(sessionsDir, coreSession.id).then((audit) => { dashboardSession.agentReportAudit = audit; }); - await settlesWithin(auditPromise, AGENT_REPORT_AUDIT_TIMEOUT_MS); + await perfTime(correlationId, "server.audit", () => settlesWithin(auditPromise, AGENT_REPORT_AUDIT_TIMEOUT_MS)); } // Enrich metadata (issue labels, agent summaries, issue titles) - await settlesWithin( - enrichSessionsMetadata([coreSession], [dashboardSession], config, registry), - METADATA_ENRICH_TIMEOUT_MS, + await perfTime(correlationId, "server.enrichMetadata", () => + settlesWithin( + enrichSessionsMetadata([coreSession], [dashboardSession], config, registry, correlationId), + METADATA_ENRICH_TIMEOUT_MS, + ), ); // Enrich PR from session metadata (written by CLI lifecycle) if (coreSession.pr) { enrichSessionPR(dashboardSession); } + perfMark(correlationId, "server.total", Date.now() - startedAt, { outcome: "200" }); recordApiObservation({ config, diff --git a/packages/web/src/app/sessions/[id]/page.tsx b/packages/web/src/app/sessions/[id]/page.tsx index cbd7efb63..aa3b46141 100644 --- a/packages/web/src/app/sessions/[id]/page.tsx +++ b/packages/web/src/app/sessions/[id]/page.tsx @@ -493,10 +493,21 @@ export default function SessionPage() { // Fetch session data (memoized to avoid recreating on every render) const fetchSession = useCallback(async () => { - if (fetchingSessionRef.current) return; + if (fetchingSessionRef.current) { + // eslint-disable-next-line no-console + if (process.env.NEXT_PUBLIC_AO_PERF === "1") console.log(`[ao-perf] cid=client client.fetch.skip-inflight id=${id}`); + return; + } fetchingSessionRef.current = true; const controller = new AbortController(); sessionFetchControllerRef.current = controller; + const perfOn = process.env.NEXT_PUBLIC_AO_PERF === "1"; + const cid = Math.random().toString(36).slice(2, 8); + const t0 = Date.now(); + if (perfOn) { + // eslint-disable-next-line no-console + console.log(`[ao-perf] cid=${cid} client.fetch.start id=${id}`); + } try { const data = await fetchJsonWithTimeout( `/api/sessions/${encodeURIComponent(id)}`, @@ -504,13 +515,23 @@ export default function SessionPage() { signal: controller.signal, timeoutMs: SESSION_FETCH_TIMEOUT_MS, timeoutMessage: `Session request timed out after ${SESSION_FETCH_TIMEOUT_MS}ms`, + headers: { "x-correlation-id": cid }, }, ); + if (perfOn) { + // eslint-disable-next-line no-console + console.log(`[ao-perf] cid=${cid} client.fetch.end=${Date.now() - t0}ms outcome=ok`); + } setSession(data as DashboardSession); setRouteError(null); setSessionMissing(false); hasLoadedSessionRef.current = true; } catch (err) { + if (perfOn) { + const reason = err instanceof Error ? err.message : "unknown"; + // eslint-disable-next-line no-console + console.log(`[ao-perf] cid=${cid} client.fetch.end=${Date.now() - t0}ms outcome=error reason=${JSON.stringify(reason)}`); + } if (pageUnloadingRef.current || controller.signal.aborted || isAbortLikeError(err)) { return; } diff --git a/packages/web/src/lib/serialize.ts b/packages/web/src/lib/serialize.ts index b2231a7a1..ca515df24 100644 --- a/packages/web/src/lib/serialize.ts +++ b/packages/web/src/lib/serialize.ts @@ -17,6 +17,7 @@ import { type ProjectConfig, type OrchestratorConfig, type PluginRegistry, + perfMark, } from "@aoagents/ao-core"; import { type DashboardSession, @@ -565,7 +566,9 @@ export async function enrichSessionsMetadata( dashboardSessions: DashboardSession[], config: OrchestratorConfig, registry: PluginRegistry, + cid?: string, ): Promise { + const traceCid = cid ?? "enrich"; const { projects, summaryPromises } = prepareSessionMetadataEnrichment( coreSessions, dashboardSessions, @@ -584,7 +587,20 @@ export async function enrichSessionsMetadata( return enrichSessionIssueTitle(dashboardSessions[i], tracker, project); }); - await Promise.allSettled([...summaryPromises, ...issueTitlePromises]); + // Time each leg independently while still running them concurrently. + const t0 = Date.now(); + const timed = (label: string, ps: Promise[]): Promise[]> => { + const start = Date.now(); + return Promise.allSettled(ps).then((r) => { + perfMark(traceCid, label, Date.now() - start, { count: ps.length }); + return r; + }); + }; + await Promise.all([ + timed("enrich.agentSummary", summaryPromises), + timed("enrich.issueTitle", issueTitlePromises), + ]); + perfMark(traceCid, "enrich.total", Date.now() - t0, { sessions: coreSessions.length }); } /** Compute dashboard stats from a list of sessions. */ diff --git a/packages/web/src/providers/MuxProvider.tsx b/packages/web/src/providers/MuxProvider.tsx index 26e33171e..569c45e2a 100644 --- a/packages/web/src/providers/MuxProvider.tsx +++ b/packages/web/src/providers/MuxProvider.tsx @@ -108,15 +108,22 @@ export function MuxProvider({ children }: { children: ReactNode }) { try { const url = buildMuxWsUrl(runtimeConfigRef.current); console.log("[MuxProvider] Connecting to", url); + const perfOn = process.env.NEXT_PUBLIC_AO_PERF === "1"; + const wsT0 = Date.now(); const ws = new WebSocket(url); // Assign immediately so cleanup can close it even during CONNECTING state wsRef.current = ws; + const firstDataPerTerminal = new Set(); ws.addEventListener("open", () => { if (isDestroyedRef.current) { ws.close(); return; } + if (perfOn) { + // eslint-disable-next-line no-console + console.log(`[ao-perf] cid=ws ws.open=${Date.now() - wsT0}ms`); + } console.log("[MuxProvider] Connected"); setStatus("connected"); reconnectAttempt.current = 0; @@ -148,6 +155,11 @@ export function MuxProvider({ children }: { children: ReactNode }) { if (msg.ch === "terminal") { const key = terminalKey(msg.id, "projectId" in msg ? msg.projectId : undefined); if (msg.type === "data") { + if (perfOn && !firstDataPerTerminal.has(key)) { + firstDataPerTerminal.add(key); + // eslint-disable-next-line no-console + console.log(`[ao-perf] cid=ws ws.firstByte=${Date.now() - wsT0}ms id=${msg.id}`); + } // Push to subscribers const subs = subscribersRef.current.get(key); if (subs) {