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
This commit is contained in:
Priyanshu Choudhary 2026-05-05 22:14:31 +05:30
parent d16a4f3e63
commit b3f522f9d9
9 changed files with 183 additions and 20 deletions

View File

@ -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,

56
packages/core/src/perf.ts Normal file
View File

@ -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<string, unknown>,
): 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<T>(
cid: string,
stage: string,
fn: () => Promise<T>,
extra?: Record<string, unknown>,
): Promise<T> {
if (!PERF_ON) return fn();
const t = Date.now();
try {
return await fn();
} finally {
perfMark(cid, stage, Date.now() - t, extra);
}
}
export function perfTimeSync<T>(
cid: string,
stage: string,
fn: () => T,
extra?: Record<string, unknown>,
): 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);
}

View File

@ -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<ReturnType<Agent["getSessionInfo"]>>;
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;

View File

@ -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<string | null> {
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<string | nul
}
}
perfMark(`codex:${workspacePath}`, "codex.findSessionFile", Date.now() - t0, {
scanned: jsonlFiles.length,
opened: openedFiles,
matched: matchedFiles,
collectMs,
found: bestMatch ? 1 : 0,
});
return bestMatch?.path ?? null;
}
@ -497,6 +517,7 @@ const sessionFileCache = new Map<string, { path: string | null; expiry: number }
async function findCodexSessionFileCached(workspacePath: string): Promise<string | null> {
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);

View File

@ -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<Socket> {
return new Promise<Socket>((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<Sock
if (settled) return;
settled = true;
sock.destroy();
perfMark(`pty:${pipePath}`, "pty.connect", Date.now() - t0, { outcome: "timeout" });
reject(new Error(`Timed out connecting to pty-host at ${pipePath} (${timeoutMs}ms)`));
}, timeoutMs);
@ -74,6 +77,7 @@ export function connectPtyHost(pipePath: string, timeoutMs = 3000): Promise<Sock
if (settled) return;
settled = true;
clearTimeout(timer);
perfMark(`pty:${pipePath}`, "pty.connect", Date.now() - t0, { outcome: "ok" });
resolve(sock);
});
@ -81,6 +85,7 @@ export function connectPtyHost(pipePath: string, timeoutMs = 3000): Promise<Sock
if (settled) return;
settled = true;
clearTimeout(timer);
perfMark(`pty:${pipePath}`, "pty.connect", Date.now() - t0, { outcome: "error" });
reject(err);
});
});
@ -218,12 +223,15 @@ export async function ptyHostGetOutput(pipePath: string, lines = 50): Promise<st
* Returns false if the pipe is unreachable (host has exited).
*/
export async function ptyHostIsAlive(pipePath: string): Promise<boolean> {
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<boolean>((resolve) => {
let settled = false;
@ -233,6 +241,11 @@ export async function ptyHostIsAlive(pipePath: string): Promise<boolean> {
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);
};

View File

@ -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,

View File

@ -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<DashboardSession | { error: string }>(
`/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;
}

View File

@ -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<void> {
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 = <T>(label: string, ps: Promise<T>[]): Promise<PromiseSettledResult<T>[]> => {
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. */

View File

@ -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<string>();
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) {