diff --git a/server/src/__tests__/inbox-mine-routes.test.ts b/server/src/__tests__/inbox-mine-routes.test.ts index 8ce064716e6..85e9c6b8a40 100644 --- a/server/src/__tests__/inbox-mine-routes.test.ts +++ b/server/src/__tests__/inbox-mine-routes.test.ts @@ -105,6 +105,16 @@ describeEmbeddedPostgres("Mine inbox snapshot routes", () => { expect(snapshot.contextIssues.find(row => row.id === resolvedTask.id)?.interruption).toMatchObject({ state: "resolved", canRetry: false }); expect(snapshot.failureRuns.map(run => run.agentId)).not.toContain(supersededAgent.id); expect(snapshotResponse.headers["cache-control"]).toBe("private, no-store"); + const timingPhases = new Map((snapshotResponse.headers["server-timing"] ?? "").split(", ").map((entry: string) => { + const match = /^([a-z_]+);dur=(\d+\.\d)$/.exec(entry); + expect(match, entry).not.toBeNull(); + return [match![1]!, Number(match![2])] as const; + })); + for (const phase of [ + "paperclip_inbox", "inbox_access", "inbox_issues", "inbox_parents", "inbox_failures", "inbox_failure_context", + "inbox_issues_query", "inbox_issues_labels", "inbox_issues_user_stats", "inbox_issues_read_stats", + "inbox_issues_last_activity", "inbox_issues_archives", "inbox_issues_live_descendants", + ]) expect(timingPhases.get(phase), phase).toBeGreaterThanOrEqual(0); expect(snapshot).not.toHaveProperty("failureError"); expect(snapshot).not.toHaveProperty("contextError"); }); diff --git a/server/src/routes/issues.ts b/server/src/routes/issues.ts index 88f2e545dc3..73e9cac0e91 100644 --- a/server/src/routes/issues.ts +++ b/server/src/routes/issues.ts @@ -41,6 +41,7 @@ import { setIssueTitle } from "../services/issue-title.js"; import { setIssueTitleSchema } from "@paperclipai/shared"; import { resolveConfirmationFromComment } from "../services/confirmation-comment-resolution.js"; import { createIssueReadTiming } from "../services/issue-read-timing.js"; +import { createInboxMineTiming } from "../services/inbox-mine-timing.js"; import { isNativeWorkspaceExportRepairCause } from "@paperclipai/shared"; import { resumeNativeWorkspaceAfterOwnerStop } from "../services/native-runtime/native-workspace-owner-recovery.js"; import { confirmNativeControllerStopped, NATIVE_CONTROLLER_HOST_UNVERIFIED } from "../services/native-runtime/native-controller-host-recovery.js"; @@ -226,6 +227,7 @@ import { issueService, type ActivityPublication, type IssueFilters, + type IssueListOptions, clampIssueListLimit, documentService, documentAnnotationService, @@ -8706,7 +8708,7 @@ export function issueRoutes( companyId: string, listFilters: IssueFilters, view: string | undefined, - options: { reportPagination?: boolean } = {}, + options: { reportPagination?: boolean; listOptions?: IssueListOptions } = {}, ): Promise { const compactView = view === "compact" || view === "index" || view === "rows"; const canReadCompanyScope = await actorCanReadCompanyScope(req, companyId); @@ -8720,6 +8722,7 @@ export function issueRoutes( const probedResult = await svc.list( companyId, pageLimit === null ? listFilters : { ...listFilters, limit: pageLimit + 1 }, + options.listOptions, ); const hasMore = pageLimit !== null && probedResult.length > pageLimit; const rawResult = hasMore ? probedResult.slice(0, pageLimit!) : probedResult; @@ -8816,6 +8819,7 @@ export function issueRoutes( router.get("/companies/:companyId/inbox/mine", async (req, res) => { const startedAt = Date.now(); + const timing = createInboxMineTiming(); const companyId = req.params.companyId as string; assertBoard(req); assertCompanyAccess(req, companyId); @@ -8825,15 +8829,15 @@ export function issueRoutes( } const userId = req.actor.userId; if (!userId) throw new HttpError(401, "A signed-in board user is required"); - const readCondition = await issueReadSqlCondition(db, req.actor); + const readCondition = await timing.time("access", () => issueReadSqlCondition(db, req.actor)); const listFilters: IssueFilters = { readCondition, touchedByUserId: userId, inboxArchivedByUserId: userId, status: INBOX_MINE_ISSUE_STATUS_FILTER, listProjection: "index", sortField: "updated", sortDir: "desc", limit: 100, includeRoutineExecutions: true, includeLiveDescendantSummary: true, }; - const readCompact = async (filters: IssueFilters, projection: "index" | "rows") => { - const prepared = await prepareIssueListForActor(req, companyId, filters, projection); + const readCompact = async (filters: IssueFilters, projection: "index" | "rows", listOptions?: IssueListOptions) => { + const prepared = await prepareIssueListForActor(req, companyId, filters, projection, { listOptions }); if (prepared.kind !== "compact") throw new Error("Expected compact inbox rows"); return prepared.body; }; @@ -8843,17 +8847,17 @@ export function issueRoutes( compute: async () => ({ kind: "inbox", body: { userId, ...await readInboxMine({ - loadIssues: () => readCompact(listFilters, "index"), - loadFailures: async () => { + loadIssues: () => timing.time("issues", () => readCompact(listFilters, "index", { timePhase: timing.listPhases })), + loadFailures: () => timing.time("failures", async () => { const permission = await access.decide({ actor: req.actor, action: "company_scope:read", resource: { type: "company", companyId } }); if (!permission.allowed) throw new HttpError(403, "Run telemetry is outside this actor's authorization boundary"); const runs = latestFailedRunsByAgent(await heartbeat.list(companyId, undefined, 200, { summary: true })); const decisions = await getHeartbeatRunReadDecisions(db, access, req.actor, runs); return runRedactions.redactForRuns(companyId, runs.map((run, index) => decisions[index] ? run : redactHeartbeatRunListRow(run)), getActorInfo(req).actorId); - }, - loadContext: (ids, projection) => readCompact({ + }), + loadContext: (ids, projection) => timing.time(projection === "index" ? "parents" : "failure_context", () => readCompact({ readCondition, issueIds: ids, listProjection: projection, limit: 100, includeRoutineExecutions: true, - }, projection), + }, projection)), sourceError: (error, source) => { logger.warn({ err: error, companyId, source }, "inbox source read failed"); return { @@ -8867,6 +8871,7 @@ export function issueRoutes( }); res.setHeader("Cache-Control", "private, no-store"); res.setHeader("X-Paperclip-Request-Cache", coordinated.cacheStatus); + res.setHeader("Server-Timing", timing.header()); if (!coordinated.response) { res.setHeader("Retry-After", String(coordinated.retryAfterSeconds ?? 1)); res.status(429).json({ error: "Too many concurrent issue-list requests for this actor/client", retryAfterSeconds: coordinated.retryAfterSeconds ?? 1 }); diff --git a/server/src/services/inbox-mine-timing.ts b/server/src/services/inbox-mine-timing.ts new file mode 100644 index 00000000000..342bc431ba0 --- /dev/null +++ b/server/src/services/inbox-mine-timing.ts @@ -0,0 +1,32 @@ +import type { IssueListPhase } from "./issues.js"; + +// Closed, content-free phase names for the Mine snapshot. This is a response +// header only (inspectable in DevTools); it emits no telemetry or spans. +export type InboxMinePhase = + | "access" | "issues" | "parents" | "failures" | "failure_context" + | `issues_${IssueListPhase}`; + +export function createInboxMineTiming() { + const start = performance.now(); + const durations = new Map(); + const time = async (phase: InboxMinePhase, read: () => Promise): Promise => { + const phaseStart = performance.now(); + try { + return await read(); + } finally { + // Batched reads (context loads in chunks) accumulate into one phase. + durations.set(phase, (durations.get(phase) ?? 0) + performance.now() - phaseStart); + } + }; + return { + time, + /** Adapts the timer to the issue list's internal phases under an `issues_` prefix. */ + listPhases: (phase: IssueListPhase, read: () => Promise) => time(`issues_${phase}`, read), + header() { + return [ + `paperclip_inbox;dur=${(performance.now() - start).toFixed(1)}`, + ...[...durations].map(([phase, duration]) => `inbox_${phase};dur=${duration.toFixed(1)}`), + ].join(", "); + }, + }; +} diff --git a/server/src/services/index.ts b/server/src/services/index.ts index 3fc81402416..6bda2cf26c4 100644 --- a/server/src/services/index.ts +++ b/server/src/services/index.ts @@ -40,6 +40,7 @@ export { ISSUE_LIST_MAX_LIMIT, issueService, type IssueFilters, + type IssueListOptions, } from "./issues.js"; export { issueThreadInteractionService } from "./issue-thread-interactions.js"; export { githubConnectionEventService, type GitHubConnectionEventPollResult } from "./github-connection-events.js"; diff --git a/server/src/services/issues.ts b/server/src/services/issues.ts index d15472087b3..cec7d7a5090 100644 --- a/server/src/services/issues.ts +++ b/server/src/services/issues.ts @@ -1865,6 +1865,18 @@ export function parseStatusFilter( .filter(Boolean); } +/** Closed, content-free phases of `issueService.list`, for response timing headers. */ +export type IssueListPhase = + | "query" | "labels" | "active_runs" | "user_stats" | "read_stats" | "last_activity" + | "archives" | "blocked_by" | "live_descendants" | "attention"; + +export interface IssueListOptions { + /** Wraps each internal read so callers can report per-phase timing. */ + timePhase?: (phase: IssueListPhase, read: () => Promise) => Promise; +} + +const untimedIssueListPhase = (_phase: IssueListPhase, read: () => Promise) => read(); + export interface IssueFilters { attention?: "blocked"; status?: string | readonly string[]; @@ -8272,7 +8284,8 @@ export function issueService(db: Db) { )).then((unread) => unread.map((row) => row.id)); }, - list: async (companyId: string, filters?: IssueFilters) => { + list: async (companyId: string, filters?: IssueFilters, options?: IssueListOptions) => { + const timePhase = options?.timePhase ?? untimedIssueListPhase; if (filters?.sortField === "id" && filters.attention) { throw unprocessable("ID ordering is not supported for blocked attention lists"); } @@ -8499,15 +8512,15 @@ export function issueService(db: Db) { : limit === undefined ? baseQuery : baseQuery.limit(limit); - const rows = (await pageQuery).map((row) => ({ + const rows = (await timePhase("query", async () => pageQuery)).map((row) => ({ ...row, description: decodeDatabaseTextPreview( row.description, ISSUE_LIST_DESCRIPTION_MAX_CHARS, ), })); - const withLabels = await withIssueLabels(db, rows); - const runMap = filters?.listProjection === "index" ? new Map() : await activeRunMapForIssues(db, withLabels); + const withLabels = await timePhase("labels", () => withIssueLabels(db, rows)); + const runMap = filters?.listProjection === "index" ? new Map() : await timePhase("active_runs", () => activeRunMapForIssues(db, withLabels)); const withRuns = withActiveRuns(withLabels, runMap); if (withRuns.length === 0) { return withRuns; @@ -8523,20 +8536,20 @@ export function issueService(db: Db) { liveDescendantCountByIssueId, ] = await Promise.all([ contextUserId - ? userCommentStatsForIssues(db, companyId, contextUserId, issueIds) + ? timePhase("user_stats", () => userCommentStatsForIssues(db, companyId, contextUserId, issueIds)) : Promise.resolve([]), contextUserId - ? userReadStatsForIssues(db, companyId, contextUserId, issueIds) + ? timePhase("read_stats", () => userReadStatsForIssues(db, companyId, contextUserId, issueIds)) : Promise.resolve([]), - lastActivityStatsForIssues(db, companyId, issueIds), + timePhase("last_activity", () => lastActivityStatsForIssues(db, companyId, issueIds)), contextUserId - ? inboxArchiveRowsForIssues(db, companyId, contextUserId, issueIds) + ? timePhase("archives", () => inboxArchiveRowsForIssues(db, companyId, contextUserId, issueIds)) : Promise.resolve([]), includeBlockedBy - ? blockedByMapForIssues(db, companyId, issueIds) + ? timePhase("blocked_by", () => blockedByMapForIssues(db, companyId, issueIds)) : Promise.resolve(new Map()), includeLiveDescendantSummary - ? liveDescendantCountMapForIssues(db, companyId, issueIds) + ? timePhase("live_descendants", () => liveDescendantCountMapForIssues(db, companyId, issueIds)) : Promise.resolve(new Map()), ]); const statsByIssueId = new Map( @@ -8552,13 +8565,15 @@ export function issueService(db: Db) { blockerAttentionByIssueId, reviewAttentionByIssueId, blockedInboxAttentionByIssueId, - ] = await Promise.all([ - filters?.listProjection === "index" ? Promise.resolve(new Map()) : listIssueBlockerAttentionMap(db, companyId, withRuns), - filters?.listProjection === "index" ? Promise.resolve(new Map()) : listIssueReviewAttentionMap(db, companyId, withRuns), - includeBlockedInboxAttention - ? listIssueBlockedInboxAttentionMap(db, companyId, withRuns) - : Promise.resolve(new Map()), - ]); + ] = filters?.listProjection === "index" && !includeBlockedInboxAttention + ? [new Map(), new Map(), new Map()] + : await timePhase("attention", () => Promise.all([ + filters?.listProjection === "index" ? Promise.resolve(new Map()) : listIssueBlockerAttentionMap(db, companyId, withRuns), + filters?.listProjection === "index" ? Promise.resolve(new Map()) : listIssueReviewAttentionMap(db, companyId, withRuns), + includeBlockedInboxAttention + ? listIssueBlockedInboxAttentionMap(db, companyId, withRuns) + : Promise.resolve(new Map()), + ])); if (!contextUserId) { return withRuns.map((row) => {