perf(api): report per-phase Server-Timing for the Mine inbox snapshot

Adds closed, content-free Server-Timing phases to GET
/api/companies/:companyId/inbox/mine (access, issues, parents, failures,
failure_context, and each svc.list lookup under issues_*), so the slow
phase is visible in DevTools without telemetry or spans.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
DottaandClaude Opus 5.5 committed 2026-11-09 17:18:25 -06:00
1 parent 09241442ea
commit 18c3f4ef7b
5 files changed
+89 -26

No files matched your search

@@ -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.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(snapshot.failureRuns.map(run => run.agentId)).not.toContain(supersededAgent.id);
expect(snapshotResponse.headers["cache-control"]).toBe("private, no-store"); 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("failureError");
expect(snapshot).not.toHaveProperty("contextError"); expect(snapshot).not.toHaveProperty("contextError");
}); });
+14 -9
View File
@@ -41,6 +41,7 @@ import { setIssueTitle } from "../services/issue-title.js";
import { setIssueTitleSchema } from "@paperclipai/shared"; import { setIssueTitleSchema } from "@paperclipai/shared";
import { resolveConfirmationFromComment } from "../services/confirmation-comment-resolution.js"; import { resolveConfirmationFromComment } from "../services/confirmation-comment-resolution.js";
import { createIssueReadTiming } from "../services/issue-read-timing.js"; import { createIssueReadTiming } from "../services/issue-read-timing.js";
import { createInboxMineTiming } from "../services/inbox-mine-timing.js";
import { isNativeWorkspaceExportRepairCause } from "@paperclipai/shared"; import { isNativeWorkspaceExportRepairCause } from "@paperclipai/shared";
import { resumeNativeWorkspaceAfterOwnerStop } from "../services/native-runtime/native-workspace-owner-recovery.js"; 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"; import { confirmNativeControllerStopped, NATIVE_CONTROLLER_HOST_UNVERIFIED } from "../services/native-runtime/native-controller-host-recovery.js";
@@ -226,6 +227,7 @@ import {
issueService, issueService,
type ActivityPublication, type ActivityPublication,
type IssueFilters, type IssueFilters,
type IssueListOptions,
clampIssueListLimit, clampIssueListLimit,
documentService, documentService,
documentAnnotationService, documentAnnotationService,
@@ -8706,7 +8708,7 @@ export function issueRoutes(
companyId: string, companyId: string,
listFilters: IssueFilters, listFilters: IssueFilters,
view: string | undefined, view: string | undefined,
options: { reportPagination?: boolean } = {}, options: { reportPagination?: boolean; listOptions?: IssueListOptions } = {},
): Promise<IssueListPreparedResponse> { ): Promise<IssueListPreparedResponse> {
const compactView = view === "compact" || view === "index" || view === "rows"; const compactView = view === "compact" || view === "index" || view === "rows";
const canReadCompanyScope = await actorCanReadCompanyScope(req, companyId); const canReadCompanyScope = await actorCanReadCompanyScope(req, companyId);
@@ -8720,6 +8722,7 @@ export function issueRoutes(
const probedResult = await svc.list( const probedResult = await svc.list(
companyId, companyId,
pageLimit === null ? listFilters : { ...listFilters, limit: pageLimit + 1 }, pageLimit === null ? listFilters : { ...listFilters, limit: pageLimit + 1 },
options.listOptions,
); );
const hasMore = pageLimit !== null && probedResult.length > pageLimit; const hasMore = pageLimit !== null && probedResult.length > pageLimit;
const rawResult = hasMore ? probedResult.slice(0, pageLimit!) : probedResult; const rawResult = hasMore ? probedResult.slice(0, pageLimit!) : probedResult;
@@ -8816,6 +8819,7 @@ export function issueRoutes(
router.get("/companies/:companyId/inbox/mine", async (req, res) => { router.get("/companies/:companyId/inbox/mine", async (req, res) => {
const startedAt = Date.now(); const startedAt = Date.now();
const timing = createInboxMineTiming();
const companyId = req.params.companyId as string; const companyId = req.params.companyId as string;
assertBoard(req); assertBoard(req);
assertCompanyAccess(req, companyId); assertCompanyAccess(req, companyId);
@@ -8825,15 +8829,15 @@ export function issueRoutes(
} }
const userId = req.actor.userId; const userId = req.actor.userId;
if (!userId) throw new HttpError(401, "A signed-in board user is required"); 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 = { const listFilters: IssueFilters = {
readCondition, touchedByUserId: userId, inboxArchivedByUserId: userId, readCondition, touchedByUserId: userId, inboxArchivedByUserId: userId,
status: INBOX_MINE_ISSUE_STATUS_FILTER, listProjection: "index", status: INBOX_MINE_ISSUE_STATUS_FILTER, listProjection: "index",
sortField: "updated", sortDir: "desc", limit: 100, sortField: "updated", sortDir: "desc", limit: 100,
includeRoutineExecutions: true, includeLiveDescendantSummary: true, includeRoutineExecutions: true, includeLiveDescendantSummary: true,
}; };
const readCompact = async (filters: IssueFilters, projection: "index" | "rows") => { const readCompact = async (filters: IssueFilters, projection: "index" | "rows", listOptions?: IssueListOptions) => {
const prepared = await prepareIssueListForActor(req, companyId, filters, projection); const prepared = await prepareIssueListForActor(req, companyId, filters, projection, { listOptions });
if (prepared.kind !== "compact") throw new Error("Expected compact inbox rows"); if (prepared.kind !== "compact") throw new Error("Expected compact inbox rows");
return prepared.body; return prepared.body;
}; };
@@ -8843,17 +8847,17 @@ export function issueRoutes(
compute: async () => ({ compute: async () => ({
kind: "inbox", kind: "inbox",
body: { userId, ...await readInboxMine({ body: { userId, ...await readInboxMine({
loadIssues: () => readCompact(listFilters, "index"), loadIssues: () => timing.time("issues", () => readCompact(listFilters, "index", { timePhase: timing.listPhases })),
loadFailures: async () => { loadFailures: () => timing.time("failures", async () => {
const permission = await access.decide({ actor: req.actor, action: "company_scope:read", resource: { type: "company", companyId } }); 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"); 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 runs = latestFailedRunsByAgent(await heartbeat.list(companyId, undefined, 200, { summary: true }));
const decisions = await getHeartbeatRunReadDecisions(db, access, req.actor, runs); 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); 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, readCondition, issueIds: ids, listProjection: projection, limit: 100, includeRoutineExecutions: true,
}, projection), }, projection)),
sourceError: (error, source) => { sourceError: (error, source) => {
logger.warn({ err: error, companyId, source }, "inbox source read failed"); logger.warn({ err: error, companyId, source }, "inbox source read failed");
return { return {
@@ -8867,6 +8871,7 @@ export function issueRoutes(
}); });
res.setHeader("Cache-Control", "private, no-store"); res.setHeader("Cache-Control", "private, no-store");
res.setHeader("X-Paperclip-Request-Cache", coordinated.cacheStatus); res.setHeader("X-Paperclip-Request-Cache", coordinated.cacheStatus);
res.setHeader("Server-Timing", timing.header());
if (!coordinated.response) { if (!coordinated.response) {
res.setHeader("Retry-After", String(coordinated.retryAfterSeconds ?? 1)); 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 }); res.status(429).json({ error: "Too many concurrent issue-list requests for this actor/client", retryAfterSeconds: coordinated.retryAfterSeconds ?? 1 });
+32
View File
@@ -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<InboxMinePhase, number>();
const time = async <T>(phase: InboxMinePhase, read: () => Promise<T>): Promise<T> => {
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: <T>(phase: IssueListPhase, read: () => Promise<T>) => 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(", ");
},
};
}
+1
View File
@@ -40,6 +40,7 @@ export {
ISSUE_LIST_MAX_LIMIT, ISSUE_LIST_MAX_LIMIT,
issueService, issueService,
type IssueFilters, type IssueFilters,
type IssueListOptions,
} from "./issues.js"; } from "./issues.js";
export { issueThreadInteractionService } from "./issue-thread-interactions.js"; export { issueThreadInteractionService } from "./issue-thread-interactions.js";
export { githubConnectionEventService, type GitHubConnectionEventPollResult } from "./github-connection-events.js"; export { githubConnectionEventService, type GitHubConnectionEventPollResult } from "./github-connection-events.js";
+32 -17
View File
@@ -1865,6 +1865,18 @@ export function parseStatusFilter(
.filter(Boolean); .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?: <T>(phase: IssueListPhase, read: () => Promise<T>) => Promise<T>;
}
const untimedIssueListPhase = <T>(_phase: IssueListPhase, read: () => Promise<T>) => read();
export interface IssueFilters { export interface IssueFilters {
attention?: "blocked"; attention?: "blocked";
status?: string | readonly string[]; status?: string | readonly string[];
@@ -8272,7 +8284,8 @@ export function issueService(db: Db) {
)).then((unread) => unread.map((row) => row.id)); )).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) { if (filters?.sortField === "id" && filters.attention) {
throw unprocessable("ID ordering is not supported for blocked attention lists"); throw unprocessable("ID ordering is not supported for blocked attention lists");
} }
@@ -8499,15 +8512,15 @@ export function issueService(db: Db) {
: limit === undefined : limit === undefined
? baseQuery ? baseQuery
: baseQuery.limit(limit); : baseQuery.limit(limit);
const rows = (await pageQuery).map((row) => ({ const rows = (await timePhase("query", async () => pageQuery)).map((row) => ({
...row, ...row,
description: decodeDatabaseTextPreview( description: decodeDatabaseTextPreview(
row.description, row.description,
ISSUE_LIST_DESCRIPTION_MAX_CHARS, ISSUE_LIST_DESCRIPTION_MAX_CHARS,
), ),
})); }));
const withLabels = await withIssueLabels(db, rows); const withLabels = await timePhase("labels", () => withIssueLabels(db, rows));
const runMap = filters?.listProjection === "index" ? new Map() : await activeRunMapForIssues(db, withLabels); const runMap = filters?.listProjection === "index" ? new Map() : await timePhase("active_runs", () => activeRunMapForIssues(db, withLabels));
const withRuns = withActiveRuns(withLabels, runMap); const withRuns = withActiveRuns(withLabels, runMap);
if (withRuns.length === 0) { if (withRuns.length === 0) {
return withRuns; return withRuns;
@@ -8523,20 +8536,20 @@ export function issueService(db: Db) {
liveDescendantCountByIssueId, liveDescendantCountByIssueId,
] = await Promise.all([ ] = await Promise.all([
contextUserId contextUserId
? userCommentStatsForIssues(db, companyId, contextUserId, issueIds) ? timePhase("user_stats", () => userCommentStatsForIssues(db, companyId, contextUserId, issueIds))
: Promise.resolve([]), : Promise.resolve([]),
contextUserId contextUserId
? userReadStatsForIssues(db, companyId, contextUserId, issueIds) ? timePhase("read_stats", () => userReadStatsForIssues(db, companyId, contextUserId, issueIds))
: Promise.resolve([]), : Promise.resolve([]),
lastActivityStatsForIssues(db, companyId, issueIds), timePhase("last_activity", () => lastActivityStatsForIssues(db, companyId, issueIds)),
contextUserId contextUserId
? inboxArchiveRowsForIssues(db, companyId, contextUserId, issueIds) ? timePhase("archives", () => inboxArchiveRowsForIssues(db, companyId, contextUserId, issueIds))
: Promise.resolve([]), : Promise.resolve([]),
includeBlockedBy includeBlockedBy
? blockedByMapForIssues(db, companyId, issueIds) ? timePhase("blocked_by", () => blockedByMapForIssues(db, companyId, issueIds))
: Promise.resolve(new Map<string, IssueRelationIssueSummary[]>()), : Promise.resolve(new Map<string, IssueRelationIssueSummary[]>()),
includeLiveDescendantSummary includeLiveDescendantSummary
? liveDescendantCountMapForIssues(db, companyId, issueIds) ? timePhase("live_descendants", () => liveDescendantCountMapForIssues(db, companyId, issueIds))
: Promise.resolve(new Map<string, number>()), : Promise.resolve(new Map<string, number>()),
]); ]);
const statsByIssueId = new Map( const statsByIssueId = new Map(
@@ -8552,13 +8565,15 @@ export function issueService(db: Db) {
blockerAttentionByIssueId, blockerAttentionByIssueId,
reviewAttentionByIssueId, reviewAttentionByIssueId,
blockedInboxAttentionByIssueId, blockedInboxAttentionByIssueId,
] = await Promise.all([ ] = filters?.listProjection === "index" && !includeBlockedInboxAttention
filters?.listProjection === "index" ? Promise.resolve(new Map<string, IssueBlockerAttention>()) : listIssueBlockerAttentionMap(db, companyId, withRuns), ? [new Map<string, IssueBlockerAttention>(), new Map<string, IssueReviewAttention>(), new Map<string, IssueBlockedInboxAttention>()]
filters?.listProjection === "index" ? Promise.resolve(new Map<string, IssueReviewAttention>()) : listIssueReviewAttentionMap(db, companyId, withRuns), : await timePhase("attention", () => Promise.all([
includeBlockedInboxAttention filters?.listProjection === "index" ? Promise.resolve(new Map<string, IssueBlockerAttention>()) : listIssueBlockerAttentionMap(db, companyId, withRuns),
? listIssueBlockedInboxAttentionMap(db, companyId, withRuns) filters?.listProjection === "index" ? Promise.resolve(new Map<string, IssueReviewAttention>()) : listIssueReviewAttentionMap(db, companyId, withRuns),
: Promise.resolve(new Map<string, IssueBlockedInboxAttention>()), includeBlockedInboxAttention
]); ? listIssueBlockedInboxAttentionMap(db, companyId, withRuns)
: Promise.resolve(new Map<string, IssueBlockedInboxAttention>()),
]));
if (!contextUserId) { if (!contextUserId) {
return withRuns.map((row) => { return withRuns.map((row) => {