Merge pull request #1512 from pikasTech/fix/issue-1422-trace-phase-timing
fix: expose Code Agent trace phase timing (#1422)
This commit is contained in:
@@ -9,6 +9,7 @@ import { createBackendPerformanceStore, backendPerformanceRouteTemplate, withBac
|
||||
import { submitAgentRunChatTurn } from "./code-agent-agentrun-adapter.ts";
|
||||
import { createCodeAgentTraceStore } from "./code-agent-trace-store.ts";
|
||||
import { createCloudApiServer } from "./server.ts";
|
||||
import { createCodeAgentChatResultStore } from "./server-code-agent-http.ts";
|
||||
|
||||
test("backend performance store templates routes and appends Cloud API metrics to loopback metrics", async () => {
|
||||
assert.equal(backendPerformanceRouteTemplate("/v1/agent/traces/trc_secret_0123456789abcdef?full=1"), "/v1/agent/traces/:id");
|
||||
@@ -37,6 +38,85 @@ test("backend performance store templates routes and appends Cloud API metrics t
|
||||
}
|
||||
});
|
||||
|
||||
test("backend performance records Code Agent trace handler phases without high-cardinality labels", async () => {
|
||||
const traceId = "trc_backend_phase_trace";
|
||||
const runId = "run_backend_phase";
|
||||
const commandId = "cmd_backend_phase";
|
||||
const traceStore = createCodeAgentTraceStore();
|
||||
const codeAgentChatResults = createCodeAgentChatResultStore();
|
||||
traceStore.append(traceId, { type: "message", role: "assistant", label: "assistant:start", sourceSeq: 1, commandId });
|
||||
traceStore.append(traceId, { type: "result", status: "completed", terminal: true, label: "result:completed", sourceSeq: 2, commandId });
|
||||
codeAgentChatResults.set(traceId, {
|
||||
status: "completed",
|
||||
conversationId: "cnv_backend_phase",
|
||||
sessionId: "ses_backend_phase",
|
||||
threadId: "thr_backend_phase",
|
||||
ownerUserId: "usr_backend_phase",
|
||||
updatedAt: "2026-06-18T00:00:00.000Z",
|
||||
agentRun: {
|
||||
adapter: "agentrun-v01",
|
||||
runId,
|
||||
commandId,
|
||||
terminalStatus: "completed",
|
||||
lastSeq: 2
|
||||
},
|
||||
finalResponse: {
|
||||
text: "done",
|
||||
traceId,
|
||||
status: "completed",
|
||||
updatedAt: "2026-06-18T00:00:00.000Z"
|
||||
},
|
||||
traceSummary: {
|
||||
source: "agentrun-command-result",
|
||||
terminalStatus: "completed",
|
||||
eventCount: 2,
|
||||
updatedAt: "2026-06-18T00:00:00.000Z"
|
||||
}
|
||||
});
|
||||
const backendPerformanceStore = createBackendPerformanceStore({ env: { POD_NAMESPACE: "hwlab-v03", HWLAB_GITOPS_TARGET: "v03" } });
|
||||
const accessController = {
|
||||
required: true,
|
||||
async authenticate() {
|
||||
return { ok: true, actor: { id: "usr_backend_phase", role: "user" }, session: { id: "web_backend_phase" } };
|
||||
},
|
||||
async getAgentSessionByTraceId(requestedTraceId: string) {
|
||||
assert.equal(requestedTraceId, traceId);
|
||||
return {
|
||||
id: "ses_backend_phase",
|
||||
sessionId: "ses_backend_phase",
|
||||
projectId: "prj_hwpod_workbench",
|
||||
ownerUserId: "usr_backend_phase",
|
||||
ownerRole: "user",
|
||||
session: {}
|
||||
};
|
||||
}
|
||||
};
|
||||
const server = createCloudApiServer({ backendPerformanceStore, traceStore, codeAgentChatResults, accessController, env: { POD_NAMESPACE: "hwlab-v03", HWLAB_GITOPS_TARGET: "v03" } });
|
||||
await new Promise<void>((resolve) => server.listen(0, "127.0.0.1", resolve));
|
||||
try {
|
||||
const address = server.address();
|
||||
assert.ok(address && typeof address === "object");
|
||||
const baseUrl = `http://127.0.0.1:${address.port}`;
|
||||
const trace = await fetch(`${baseUrl}/v1/agent/traces/${traceId}?projectId=prj_hwpod_workbench&limit=1`);
|
||||
assert.equal(trace.status, 200);
|
||||
const serverTiming = trace.headers.get("server-timing") ?? "";
|
||||
assert.match(serverTiming, /trace-project-check;dur=/u);
|
||||
assert.match(serverTiming, /trace-paginate;dur=/u);
|
||||
assert.match(serverTiming, /total;dur=/u);
|
||||
const payload = await trace.json();
|
||||
assert.equal(payload.range.returned, 1);
|
||||
|
||||
const metrics = await fetch(`${baseUrl}/v1/web-performance/metrics`);
|
||||
const text = await metrics.text();
|
||||
assert.equal(metrics.status, 200);
|
||||
assert.match(text, /hwlab_cloud_api_request_phase_duration_seconds_count\{[^}]*route="\/v1\/agent\/traces\/:id"[^}]*phase="trace_project_check"[^}]*\} 1/u);
|
||||
assert.match(text, /hwlab_cloud_api_request_phase_duration_seconds_count\{[^}]*route="\/v1\/agent\/traces\/:id"[^}]*phase="trace_paginate"[^}]*\} 1/u);
|
||||
assert.doesNotMatch(text, /trc_backend_phase_trace|run_backend_phase|cmd_backend_phase|ses_backend_phase|cnv_backend_phase/u);
|
||||
} finally {
|
||||
await new Promise<void>((resolve, reject) => server.close((error) => error ? reject(error) : resolve()));
|
||||
}
|
||||
});
|
||||
|
||||
test("AgentRun adapter records upstream timing through backend performance context", async () => {
|
||||
const calls: Array<{ method?: string; path: string; body?: any }> = [];
|
||||
const agentRunServer = createHttpServer(async (request, response) => {
|
||||
|
||||
@@ -1144,12 +1144,12 @@ export async function handleCodeAgentTurnHttp(request, response, url, options) {
|
||||
return;
|
||||
}
|
||||
const requestOptions = codeAgentRequestScopedOptions(options);
|
||||
const projectMismatch = await traceProjectMismatchSnapshot(traceId, url, requestOptions, "turn");
|
||||
const projectMismatch = await measureCodeAgentHttpPhase(requestOptions, "turn_project_check", () => traceProjectMismatchSnapshot(traceId, url, requestOptions, "turn"));
|
||||
if (projectMismatch) {
|
||||
sendJson(response, projectMismatch.statusCode, projectMismatch.body);
|
||||
return;
|
||||
}
|
||||
const resolved = await resolveCodeAgentTurnStatusSnapshot(traceId, requestOptions);
|
||||
const resolved = await measureCodeAgentHttpPhase(requestOptions, "turn_resolve_status", () => resolveCodeAgentTurnStatusSnapshot(traceId, requestOptions));
|
||||
sendJson(response, resolved.statusCode, resolved.body);
|
||||
}
|
||||
|
||||
@@ -1164,7 +1164,7 @@ async function resolveCodeAgentTurnStatusSnapshot(traceId, options) {
|
||||
let turnRefreshSatisfiedByResultSync = false;
|
||||
if (adapterEnabled && (result?.agentRun?.runId || !result)) {
|
||||
try {
|
||||
const synced = await syncAgentRunChatResult({ traceId, currentResult: result, options: refreshOptions, traceStore });
|
||||
const synced = await measureCodeAgentHttpPhase(options, "turn_result_sync", () => syncAgentRunChatResult({ traceId, currentResult: result, options: refreshOptions, traceStore }));
|
||||
result = synced.result ?? result;
|
||||
turnRefreshSatisfiedByResultSync = synced.eventsRefreshed === true || synced.resultSynced === true || synced.terminalRefreshSkipped === true;
|
||||
if (result && !canAccessOwnedResult(result, options.actor)) return forbiddenTurnSnapshot(traceId);
|
||||
@@ -1193,7 +1193,7 @@ async function resolveCodeAgentTurnStatusSnapshot(traceId, options) {
|
||||
let agentRunResult = result?.agentRun ? result : null;
|
||||
if (!agentRunResult && adapterEnabled) {
|
||||
try {
|
||||
agentRunResult = await loadPersistedAgentRunResult(traceId, options);
|
||||
agentRunResult = await measureCodeAgentHttpPhase(options, "turn_load_persisted_result", () => loadPersistedAgentRunResult(traceId, options));
|
||||
} catch {
|
||||
agentRunResult = null;
|
||||
}
|
||||
@@ -1203,10 +1203,10 @@ async function resolveCodeAgentTurnStatusSnapshot(traceId, options) {
|
||||
let refreshError = null;
|
||||
if (agentRunResult?.agentRun && !turnRefreshSatisfiedByResultSync && !resultPollError) {
|
||||
try {
|
||||
const refreshedTrace = await refreshAgentRunTrace({ traceId, result: agentRunResult, options: refreshOptions, traceStore });
|
||||
const refreshedTrace = await measureCodeAgentHttpPhase(options, "turn_trace_refresh", () => refreshAgentRunTrace({ traceId, result: agentRunResult, options: refreshOptions, traceStore }));
|
||||
agentRunResult = options.codeAgentChatResults?.get?.(traceId) ?? agentRunResult;
|
||||
if (traceNeedsCommandResultSync(agentRunResult, refreshedTrace)) {
|
||||
const synced = await syncAgentRunChatResult({ traceId, currentResult: agentRunResult, options: refreshOptions, traceStore, appendResultEvent: false, refreshEvents: false, forceResultSync: true });
|
||||
const synced = await measureCodeAgentHttpPhase(options, "turn_force_result_sync", () => syncAgentRunChatResult({ traceId, currentResult: agentRunResult, options: refreshOptions, traceStore, appendResultEvent: false, refreshEvents: false, forceResultSync: true }));
|
||||
agentRunResult = synced.result ?? agentRunResult;
|
||||
}
|
||||
if (isTraceCommandTerminalStatus(agentRunResult?.status)) {
|
||||
@@ -1217,8 +1217,10 @@ async function resolveCodeAgentTurnStatusSnapshot(traceId, options) {
|
||||
}
|
||||
}
|
||||
|
||||
const snapshot = traceSnapshotWithTerminalEvidence(traceStore.snapshot(traceId), agentRunResult ?? result, traceId, refreshError);
|
||||
const body = codeAgentTurnStatusPayload({ traceId, result: agentRunResult ?? result, snapshot, resultPollError, refreshError, options });
|
||||
const body = await measureCodeAgentHttpPhase(options, "turn_payload", () => {
|
||||
const snapshot = traceSnapshotWithTerminalEvidence(traceStore.snapshot(traceId), agentRunResult ?? result, traceId, refreshError);
|
||||
return codeAgentTurnStatusPayload({ traceId, result: agentRunResult ?? result, snapshot, resultPollError, refreshError, options });
|
||||
});
|
||||
return { statusCode: body.ok ? 200 : 404, body };
|
||||
}
|
||||
|
||||
@@ -1245,6 +1247,11 @@ function codeAgentRequestScopedOptions(options = {}) {
|
||||
};
|
||||
}
|
||||
|
||||
async function measureCodeAgentHttpPhase(options, phase, callback) {
|
||||
const perf = options?.backendPerformance;
|
||||
return perf && typeof perf.measure === "function" ? await perf.measure(phase, callback) : await callback();
|
||||
}
|
||||
|
||||
function forbiddenTurnSnapshot(traceId) {
|
||||
return {
|
||||
statusCode: 403,
|
||||
@@ -2524,7 +2531,7 @@ export async function handleCodeAgentTraceHttp(request, response, url, options)
|
||||
return;
|
||||
}
|
||||
const requestOptions = codeAgentRequestScopedOptions(options);
|
||||
const projectMismatch = await traceProjectMismatchSnapshot(traceId, url, requestOptions, "trace");
|
||||
const projectMismatch = await measureCodeAgentHttpPhase(requestOptions, "trace_project_check", () => traceProjectMismatchSnapshot(traceId, url, requestOptions, "trace"));
|
||||
if (projectMismatch) {
|
||||
sendJson(response, projectMismatch.statusCode, projectMismatch.body);
|
||||
return;
|
||||
@@ -2540,7 +2547,7 @@ export async function handleCodeAgentTraceHttp(request, response, url, options)
|
||||
return;
|
||||
}
|
||||
|
||||
let agentRunResult = result?.agentRun ? result : await loadPersistedAgentRunResult(traceId, requestOptions);
|
||||
let agentRunResult = result?.agentRun ? result : await measureCodeAgentHttpPhase(requestOptions, "trace_load_persisted_result", () => loadPersistedAgentRunResult(traceId, requestOptions));
|
||||
let refreshError = null;
|
||||
if (agentRunResult && !canAccessOwnedResult(agentRunResult, requestOptions.actor)) {
|
||||
sendJson(response, 403, {
|
||||
@@ -2557,10 +2564,10 @@ export async function handleCodeAgentTraceHttp(request, response, url, options)
|
||||
const terminalSnapshotRefreshSatisfied = traceRefreshSatisfiedByTerminalSnapshot(agentRunResult, existingSnapshot);
|
||||
const snapshot = terminalSnapshotRefreshSatisfied
|
||||
? existingSnapshot
|
||||
: await refreshAgentRunTrace({ traceId, result: agentRunResult, options: requestOptions, traceStore });
|
||||
: await measureCodeAgentHttpPhase(requestOptions, "trace_trace_refresh", () => refreshAgentRunTrace({ traceId, result: agentRunResult, options: requestOptions, traceStore }));
|
||||
agentRunResult = requestOptions.codeAgentChatResults?.get?.(traceId) ?? agentRunResult;
|
||||
if (!terminalSnapshotRefreshSatisfied && traceNeedsCommandResultSync(agentRunResult, snapshot)) {
|
||||
const synced = await syncAgentRunChatResult({ traceId, currentResult: agentRunResult, options: requestOptions, traceStore, appendResultEvent: false, refreshEvents: false, forceResultSync: true });
|
||||
const synced = await measureCodeAgentHttpPhase(requestOptions, "trace_result_sync", () => syncAgentRunChatResult({ traceId, currentResult: agentRunResult, options: requestOptions, traceStore, appendResultEvent: false, refreshEvents: false, forceResultSync: true }));
|
||||
agentRunResult = synced.result ?? agentRunResult;
|
||||
}
|
||||
if (isTraceCommandTerminalStatus(agentRunResult?.status)) {
|
||||
@@ -2576,8 +2583,11 @@ export async function handleCodeAgentTraceHttp(request, response, url, options)
|
||||
return;
|
||||
}
|
||||
|
||||
const snapshot = traceStore.snapshot(traceId);
|
||||
sendJson(response, 200, paginateTraceSnapshot(traceSnapshotWithTerminalEvidence(snapshot, agentRunResult, traceId, refreshError), pageOptions));
|
||||
const body = await measureCodeAgentHttpPhase(requestOptions, "trace_paginate", () => {
|
||||
const snapshot = traceStore.snapshot(traceId);
|
||||
return paginateTraceSnapshot(traceSnapshotWithTerminalEvidence(snapshot, agentRunResult, traceId, refreshError), pageOptions);
|
||||
});
|
||||
sendJson(response, 200, body);
|
||||
}
|
||||
|
||||
function codeAgentTracePageOptions(url) {
|
||||
|
||||
Reference in New Issue
Block a user