From ac0d0374f2cca2f57b936d898c566303ecb61fb9 Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Mon, 9 Nov 2026 09:06:37 -0600 Subject: [PATCH] perf(issue-detail): measure task opens on real instances (#20276) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - People open a task from their issues list to see what an agent is doing and to reply > - On a busy staging instance, the composer and the latest messages take 1.1โ€“2.0 s to appear after a click. For one task with a slow run log, they took 13.9 s > - Local fixtures do not reproduce this. They do not have real network round trips, real server contention, or real object-store latency > - This pull request adds the measurement we need: a browser harness that times a task open on a real instance, and a Server-Timing entry on every API response that separates server time from network time > - It also records the staging baseline and the improvement plan > - The benefit is that each later performance change can be measured on real data with the same tool, before and after deploy ## Linked Issues or Issue Description **Problem or motivation** Opening a task from the issues list is slow on instances with real data. The composer and the latest chat messages can take seconds to appear. We could not measure this on staging in a repeatable way. We also could not tell server time from network and queueing time for most API requests. **Proposed solution** Add a reusable browser harness for task opens, and add a `paperclip_api` Server-Timing entry to every API response. **Alternatives considered** Local Playwright fixtures only. They do not reproduce real network round trips, server contention or object-store latency, so they did not show the delays that people see. Per-endpoint Server-Timing only. It does not cover the many other requests that run during a task open. **Roadmap alignment** This is measurement for existing task-loading behaviour. It does not add product features. The staging baseline and the measured causes are in `doc/plans/2026-11-09-task-loading-performance.md`. Follow-up pull requests change the loading behaviour itself, starting with #20277. ## What Changed - Added `server/src/middleware/api-server-timing.ts`. Every `/api` response now has a `paperclip_api;dur=` Server-Timing entry. The value is the server time from request arrival until headers are written, including admission waits. The entry is appended, so the existing `paperclip_issue` phases stay first. - Registered the middleware first in `server/src/app.ts`. - Added `tests/perf/issue-detail/staging-click-harness.js`. It clicks a task row and records, frame by frame, when the composer and the latest message become visible, layout shifts, movement of the latest message, and the requests that run before the page is ready. The summary labels each sample instead of using the task reference. It replaces query values and every path segment that contains a digit. A fetch that is still running when the sample ends is listed as pending. - Documented the harness in `tests/perf/issue-detail/README.md`. - Added the dated plan `doc/plans/2026-11-09-task-loading-performance.md` with the staging baseline, the causes, and the prioritized slices. ## Verification - `cd server && npx vitest run src/__tests__/api-server-timing.test.ts`. 3 tests pass. They cover the JSON responses, the time spent in earlier middleware, preserving route phases, and explicit `writeHead` calls. - `tests/perf/issue-detail/issue-detail.perf.spec.ts` reads the first `dur=` value. That value is still `paperclip_issue`. - The harness was used on staging to capture the baseline in the plan document. ## Risks - Low risk. The header has only a duration, with no request, user or company data. - The middleware wraps `res.writeHead` once for each request. This is the same pattern that `on-headers` uses. - Server-Timing is visible to same-origin scripts only. No `Timing-Allow-Origin` header is added. ## Model Used - Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, used in Claude Code with tool use (shell, browser automation, file editing). ## Checklist - [x] I have included a thinking path that traces from project context to this change - [x] I have specified the model used (with version and capability details) - [x] I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work - [x] I have searched GitHub for duplicate or related PRs and linked them above - [x] I have either (a) linked existing issues with `Fixes: #` / `Closes #` / `Refs #` OR (b) described the issue in-PR following the relevant issue template - [x] I have not referenced internal/instance-local Paperclip issues or links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip` URLs) - [x] My branch name describes the change (e.g. `docs/...`, `fix/...`) and contains no internal Paperclip ticket id or instance-derived details - [x] I have run tests locally and they pass - [x] I have added or updated tests where applicable - [x] I have updated relevant documentation to reflect my changes - [x] I have considered and documented any risks above - [ ] All Paperclip CI gates are green - [ ] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [ ] I will address all Greptile and reviewer comments before requesting merge ๐Ÿค– Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5.5 --- .../2026-11-09-task-loading-performance.md | 269 ++++++++++++++++++ .../src/__tests__/api-server-timing.test.ts | 62 ++++ server/src/app.ts | 3 + server/src/middleware/api-server-timing.ts | 27 ++ tests/perf/issue-detail/README.md | 27 ++ .../issue-detail/staging-click-harness.js | 182 ++++++++++++ 6 files changed, 570 insertions(+) create mode 100644 doc/plans/2026-11-09-task-loading-performance.md create mode 100644 server/src/__tests__/api-server-timing.test.ts create mode 100644 server/src/middleware/api-server-timing.ts create mode 100644 tests/perf/issue-detail/staging-click-harness.js diff --git a/doc/plans/2026-11-09-task-loading-performance.md b/doc/plans/2026-11-09-task-loading-performance.md new file mode 100644 index 00000000000..b6094e85345 --- /dev/null +++ b/doc/plans/2026-11-09-task-loading-performance.md @@ -0,0 +1,269 @@ +# Task loading performance: latest chat in ~0 ms + +Date: 2026-11-09 ยท Branch: `claude/task-loading-perf-154fea` (base `33a23e0246`) + +## Goal + +Opening a task from the "Mine" issues list should show the composer and the latest +messages almost immediately. If an agent is live, the user should catch up on its +progress. If the run is done, the user should see the last messages. Older history +loads only when the user asks for it. The page must not move content around: +skeletons must have the same size as the content that replaces them, and the latest +message must not move once it is visible. + +### Finish conditions + +The user-facing endpoint is reviewable PRs with these results remeasured on staging. + +| # | Condition | Baseline (below) | Target | +|---|---|---|---| +| F1 | Revisit a task whose data is cached โ†’ composer and latest message visible | 144โ€“170 ms (14.6 s when the run log gates) | โ‰ค 100 ms, for every task | +| F2 | Hover, then click a row โ†’ composer and latest message visible | not prefetched today | โ‰ค 150 ms | +| F3 | Click a row with no prefetch (data not cached) โ†’ composer and latest message visible | 1.1โ€“2.0 s (13.9 s when the run log gates) | โ‰ค 600 ms p50 (one round trip) | +| F4 | Hard load of a task URL โ†’ content painted | 5.2 s | โ‰ค 1.5 s | +| F5 | Layout stability | CLS 0.035 on every click | 0 inside the chat; the latest message never moves after it first appears | +| F6 | API requests started before the page is ready | ~30 on a click, ~70 on a hard load | โ‰ค 3 on the critical path | +| F7 | Live run | โ€” | Shows the current run status within F1โ€“F3 and streams new output | + +The evidence for each condition is a timing sample from the staging harness (Phase 0): +5 tasks ร— 3 starting states, run serially, reporting the median and range. The same +journey is repeated after each PR is deployed. + +## Baseline on staging, measured 2026-11-09 + +- **Environment:** the shared staging instance, one company with production-like data, desktop Chrome, HTTP/2, no throttling. +- **JS cache:** the JS bundle was already in the browser cache. +- **Harness:** an in-page harness that checks every animation frame for the thread mount, a visible composer, the latest `[data-conversation-message]` being visible in the viewport, layout shifts, and resource timing. + +### Click from the list (data not cached in React Query) + +| Task | Composer + latest message | Thread mounted | API requests (total / before ready) | What it waited on | +|---|---|---|---|---| +| Task A | 1,107 ms | 38 ms | 35 / 33 | `GET /issues/:id` 1,016 ms; activity, runs, recent-comments ~710 ms each | +| Task B | 1,190 ms | 56 ms | 49 / 31 | `GET /issues/:id` 1,289 ms; ~10 parallel queries of 800โ€“900 ms | +| Task C | 1,977 ms | 935 ms | 41 / 28 | a serial chain: work-products, activity and runs started at ~900 ms | +| Task D | 2,014 ms | 540 ms | โ€” | โ€” | +| **Task E** | **13,862 ms** | 40 ms | 78 / 76 | **`GET /heartbeat-runs/:id/log` 11,150 ms** | + +### Revisit (React Query cache warm) + +| Task | Composer + latest message | Note | +|---|---|---| +| Task D | 144 ms | | +| Task B | 170 ms | | +| **Task E** | **14,651 ms** | The run log is fetched again and gates the page again (13.2 s) | + +### Hard load (direct URL, JS from cache) + +| Task | Document TTFB | First contentful paint | Header paint | **Content paint** | API requests before content | +|---|---|---|---|---|---| +| Task F | 478 ms | 676 ms | 2,416 ms | **5,211 ms** | 70 | +| Task G | 4,558 ms (outlier; a later fetch of the same HTML took 207โ€“389 ms) | 4,980 ms | 6,587 ms | 7,841 ms | 72 | + +The page parses about 7.7 MB of JS, even with all of it served from the cache. + +### Server latency floor + +Each endpoint was requested 3 times in a row, without competing requests. + +- `/api/cli-auth/me` 272โ€“365 ms. This trivial authenticated request sets the floor for each round trip from this machine. +- `/api/issues/:id/recent-comments` 300 ms. +- `/api/issues/:id?view=core` 464โ€“595 ms, with one sample at 3.2 s. +- `/api/issues/:id` full 863โ€“996 ms. +- `/api/issues/:id/activity?view=recent` 520โ€“1,061 ms. +- `/api/issues/:id/runs?view=recent` 374โ€“1,125 ms. + +During a click, ~30 requests run at the same time, and each slows to 700โ€“1,500 ms. + +**Server-Timing** samples: +- `issue_lookup` took 893โ€“908 ms in one cold sample and ~100โ€“160 ms in others. +- `paperclip_issue` (full view) took 736โ€“1,813 ms. + +### Run log read + +Task E has a failed run with no saved reply. Its log comes from the object-store journal (`s3_segments`). + +| Read | Time | +|---|---| +| Tail, 32 KB at offset 414,581, with `alignStartToRecord=true` (what the UI sends) | 11.9 s, 11.2 s | +| Same tail without alignment | 6.1 s | +| Same 32 KB at offset 0 | 2.0 s | + +### Repeated and polling requests + +These requests were made during one 17 s visit (Task E): + +| Request | Count | +|---|---| +| `issues/summaries?ids` | 22 | +| `/issues/:id/live-runs` (two id forms) | 11 | +| `/issues/:id/browsers` | 6 | +| `companies/:id/agents` (60 KB each) | 6 | +| `companies/:id/live-runs` | 3 | +| descendant, created-from and parent lists | 2โ€“3 each | + +## Where the time goes + +1. **The run transcript blocks the whole chat.** + - The composer and messages stay hidden until history is ready: `historyPending = initialHistoryPending || planLoading || transcriptHistoryPending || chatMetadataPending` (`ui/src/components/TaskChatThread.tsx:3216`). + - The composer dock is hidden until then too (`concealed={!historyRevealed}`, `TaskChatThread.tsx:3524`). + - `transcriptHistoryPending` waits for every failed run, live run, or run without a reply to finish hydrating. + - The only cap is the 15 s reveal timeout. One slow log read therefore hides even saved messages the page has already fetched. +2. **Tail reads from the object-store log are serial.** + - `readRange` in `server/src/services/object-byte-journal.ts:525` visits index nodes and payload segments one by one, with one S3 GET for each. + - A tail read crosses many small segments. + - `alignStartToRecord` repeats the whole traversal for the 32 KB before it (`object-run-log-store.ts:388`), which doubles the cost. + - Nothing caches these objects, although segments cannot change after they are written. +3. **The page waits on many queries.** + - `initialHistoryPending` waits on about ten queries: recent comments, interactions, attachments, work products, activity, runs, comment runs, comment input facts, live runs and active run. + - The thread also waits on the plan, transcripts and conversation metadata. + - Even when every query is fast, the reveal waits for the slowest of ~30 concurrent requests that compete on the server. +4. **Prefetch covers only part of what the page waits on.** + - `prefetchIssueDetailForNavigation` (`ui/src/lib/issueDetailCache.ts:227`) warms only the core view and recent comments. + - Everything else that gates the reveal still starts on click. + - Nothing is kept across reloads (no React Query persister). A hard load is therefore always cold. +5. **The full issue request waits for the core request.** + - The full `GET /issues/:id` starts only after `view=core` resolves (`IssueDetail.tsx:3361`). +6. **Non-critical work competes with the reveal.** + - chat-binding, email tasks, browsers, external-objects, feedback votes, tree holds, projects, related-issue lists and polling all start on the click and share server capacity with the requests that matter. +7. **The hard-load path is heavy.** + - It parses about 7.7 MB of JS. + - It sends 70 API requests before content appears. + - The header paints 1.5 s after navigation starts, and the content 4.3 s after. + +## Feedback loop + +| Question | Loop and environment | Cost per iteration | +|---|---|---| +| Is the user-visible timing better? | Staging harness (Phase 0) run through Chrome against real data, after each deploy | ~5 min per sample set, plus the deploy | +| Does a UI gate or prefetch change help? | Local `tests/perf/issue-detail` Playwright harness with production assets (`PAPERCLIP_UI_DEV_MIDDLEWARE=false`), plus a CDP network RTT of ~150 ms so local results match staging round trips | ~2โ€“3 min | +| Is the object-store log read faster? | Server unit or bench test against a fake object provider with ~60 ms latency per GET and a fixture log with many small segments. Confirm on staging with Honeycomb traces (GET count per request) | seconds | +| Did we break layout? | Existing `layout-stability`, `loading-layout`, `compact-startup` and `saved-reply-startup` specs, plus the frame recorder in the harness | ~3 min | + +Two things local runs cannot show: real multi-tenant contention and real S3 latency. Every +result therefore gets a staging check before we call it done. + +## Plan: PR slices in priority order + +### P0. Measurement, before any changes (small PR) + +- Commit the staging click harness as `tests/perf/issue-detail/staging-click-harness.js`. It runs in the page and records, per sample: + - T_composer and T_latest + - T_thread + - layout shifts and moves of the latest message + - requests before ready, and the request that released the reveal +- Use the same harness against local runs, so every comparison uses the same measurement. +- Add `Server-Timing` to the endpoints the reveal waits on: + - `recent-comments` + - `activity` + - `runs` + - `live-runs` + - `heartbeat-runs/:id/log`, including its object GET count and total GET time + - `heartbeat-runs/:id/events` +- Add a local fixture with a failed run that has no reply and a multi-segment object log. Give the fake provider realistic per-GET latency so it reproduces Task E. + +### P1. Show the composer and saved messages without waiting for transcripts (UI, biggest win) + +- Remove `transcriptHistoryPending` from the reveal gate. + - Runs that are still hydrating render in a **reserved, fixed-height run slot**: a collapsed "agent activity" row with the same geometry as the loaded collapsed state. That row expands only when the user acts, so its content never pushes the latest message. + - Live runs show their status line right away and stream output as it arrives. +- Never hide the composer dock behind history. + - It is pinned to the bottom of the viewport and its height comes from the composer itself, so it can render on the first frame with the thread skeleton above it. + - Keep the draft and focus behaviour. +- Narrow `initialHistoryPending` to what defines the structure of the latest view: recent comments and interactions. + - Activity, runs, attachments and work products go into reserved slots or load after the reveal. +- Expected result on staging: + - Task E drops from 13.9 s to the time of the other tasks (~1.1โ€“2 s). + - The tail of every other cold click gets shorter, because the slowest of ~10 queries no longer decides the reveal. +- Regression journeys: + - deep link to an older comment + - Back restore + - a draft during refetch + - failed or stalled requests + - a run that finishes while the page is open + +### P2. Fix object-store log tail reads (server) + +- In `readRange`, fetch the payload segments for a range in parallel, with limited concurrency (~8). +- Align to a record in **one pass**: read `[offset โˆ’ 32 KB, end)` once and cut at the last newline. Do not re-traverse. +- Cache immutable segments and index nodes per process, in a bounded LRU keyed by content key and company. +- Optionally: + - Store a tail pointer or the last index node in the head, so a tail read skips the walk from the root. + - Compact small segments when the log closes. +- Target: a 32 KB tail read under 500 ms on staging, with no stalls of several seconds. The staging check is Honeycomb GET counts plus the harness. +- Also benefits: every live run viewer and the polling fallback. + +### P3. Load the data before the click (target ~0 ms) + +- **Prefetch everything the reveal waits on.** + - Add the P1-narrowed set to `prefetchIssueDetailForNavigation` (`issueDetailCache.ts:227`). + - Trigger it on `pointerover`, `pointerdown`, `focusin` and keyboard selection, which already exist for code and core data. + - Also trigger it on idle for the first few visible rows of "Mine". + - Respect `staleTime` and company scope. +- **Add a chat bootstrap endpoint**, `GET /issues/:id/chat-bootstrap`. It returns one company-scoped response with: + - the core issue + - the latest N timeline items, already merged: comments, interactions, run summaries and the latest status of a live run + - the composer facts: assignee, model and permissions + - a `cursor` used to catch up after the response + - This replaces ~10 gating round trips with one, so the floor becomes ~300 ms on a cold click. + - The existing granular queries are seeded from the bootstrap response, so invalidation keeps working unchanged. + - Contracts change in shared, server and UI. +- **Keep the last-seen chat window per task in IndexedDB.** + - Bounded size, scoped by company and user, cleared on logout or company change. + - On revisit or hard load, render from it on the first frame, then revalidate with `?since=cursor`. + - New items append under the bottom anchor, so the reading position does not move. + - A small "syncing" indicator sits in a reserved slot. + - Freshness is guaranteed by the catch-up read plus the websocket subscription, not by a time window. +- **Run full detail in parallel with core.** Start full detail at the same time as `view=core` instead of after it (`IssueDetail.tsx:3361`). Drop that ordering if the bootstrap endpoint makes the core view unnecessary. + +### P4. Remove fan-out and polling noise + +- Defer the requests the reveal does not need (chat-binding, email tasks, browsers, external-objects, feedback votes, tree holds, projects, descendant, created-from and parent lists). Start them in `requestIdleCallback` after the reveal, or when their UI is opened. +- Find out why `issues/summaries?ids` runs about every 0.5โ€“1 s, and why `agents` (60 KB), `live-runs` and `browsers` refetch repeatedly while a task is open. + - Batch those requests. + - Remove duplicates. + - Rely on websocket invalidation instead. +- Goal: โ‰ค 3 requests on the critical path, and a quiet page after load. +- These changes also lower load on the staging server. + +### P5. Hard-load path + +After P3, a hard load can render from the persisted chat window. The remaining work: + +- Profile the 1.5 s between navigation and header paint: JS parse and evaluate of 7.7 MB, and module initialisation. +- Measure the 70 requests made before content and remove the ones not needed. +- Consider inlining the chat bootstrap for the requested URL into the HTML response, so the first paint needs no extra round trip. + +### P6. Layout contract + +- Find the `DIV` that shifts (CLS 0.035) ~25โ€“40 ms after every click. It is most likely the swap from the list to the detail skeleton. +- Make the skeleton's geometry match the header, thread and composer exactly. +- Add the harness checks "latest message never moves after first visible" and "composer never moves" to the existing frame-recording specs. + +## Acceptance matrix (applies to every slice) + +| Case | Check | +|---|---| +| Done task with a saved reply, short and long thread | Latest message and composer within target; no movement | +| Failed run with no reply (Task E shape) | Not gated by the transcript; run slot is reserved | +| Live run | Status visible right away; new output streams; no duplicate after catch-up | +| Deep link to an older comment, Back restore | Anchor kept | +| Draft typed during background refresh, navigating away and back | Draft kept; no duplicate send | +| Company switch, logout | Persisted cache isolated and cleared | +| Websocket down | Polling fallback still catches up | + +## Deferred / follow-ups + +- Server-side `issue_lookup` by identifier sometimes takes ~900 ms. Hand it to `fix-slow-queries` with Neon evidence if it persists after P4 reduces contention. +- The 4.5 s document TTFB outlier on one hard load. Watch for it in the harness; it may be an instance wake-up. + +## State + +- [x] Staging baseline captured (this doc) +- [ ] P0 harness + Server-Timing +- [ ] P1 ungate transcripts / composer +- [ ] P2 object log reads +- [ ] P3 prefetch + bootstrap + persisted window +- [ ] P4 fan-out/polling +- [ ] P5 hard load +- [ ] P6 layout contract diff --git a/server/src/__tests__/api-server-timing.test.ts b/server/src/__tests__/api-server-timing.test.ts new file mode 100644 index 00000000000..b3015d324df --- /dev/null +++ b/server/src/__tests__/api-server-timing.test.ts @@ -0,0 +1,62 @@ +import express from "express"; +import { createServer } from "node:http"; +import type { AddressInfo } from "node:net"; +import { afterEach, describe, expect, it } from "vitest"; +import { apiServerTiming } from "../middleware/api-server-timing.js"; + +const openServers: Array> = []; + +afterEach(async () => { + await Promise.all(openServers.splice(0).map((server) => new Promise((resolve, reject) => { + server.close((err) => err ? reject(err) : resolve()); + }))); +}); + +async function serve(app: express.Express) { + const server = createServer(app); + openServers.push(server); + await new Promise((resolve) => server.listen(0, "127.0.0.1", resolve)); + return `http://127.0.0.1:${(server.address() as AddressInfo).port}`; +} + +describe("apiServerTiming", () => { + it("reports the server time for a JSON response, including time spent before the handler", async () => { + const app = express(); + app.use("/api", apiServerTiming()); + app.use("/api", (_req, _res, next) => setTimeout(next, 25)); + app.get("/api/thing", (_req, res) => res.json({ ok: true })); + const response = await fetch(`${await serve(app)}/api/thing`); + + expect(response.status).toBe(200); + const match = /^paperclip_api;dur=(\d+(?:\.\d+)?)$/.exec(response.headers.get("server-timing") ?? ""); + expect(match).not.toBeNull(); + expect(Number(match![1])).toBeGreaterThanOrEqual(20); + }); + + it("keeps route-specific phases and appends the total after them", async () => { + const app = express(); + app.use("/api", apiServerTiming()); + app.get("/api/issue", (_req, res) => { + res.setHeader("Server-Timing", "paperclip_issue;dur=3.0, issue_lookup;dur=1.0"); + res.status(204).end(); + }); + const response = await fetch(`${await serve(app)}/api/issue`); + + expect(response.headers.get("server-timing")).toMatch( + /^paperclip_issue;dur=3\.0, issue_lookup;dur=1\.0, paperclip_api;dur=\d+(\.\d+)?$/, + ); + }); + + it("times responses with explicit writeHead calls and errors once", async () => { + const app = express(); + app.use("/api", apiServerTiming()); + app.get("/api/raw", (_req, res) => { + res.writeHead(404, { "content-type": "text/plain" }); + res.end("missing"); + }); + const response = await fetch(`${await serve(app)}/api/raw`); + + expect(response.status).toBe(404); + expect(response.headers.get("server-timing")?.match(/paperclip_api/g)).toHaveLength(1); + }); +}); diff --git a/server/src/app.ts b/server/src/app.ts index 9bc926dd912..2a3560b5014 100644 --- a/server/src/app.ts +++ b/server/src/app.ts @@ -242,6 +242,7 @@ import { } from "./http/body-limits.js"; import { COMPANY_IMPORT_API_PATH } from "./routes/company-import-paths.js"; import { apiCompression } from "./middleware/api-compression.js"; +import { apiServerTiming } from "./middleware/api-server-timing.js"; import { chatWebhookBodyParser } from "./middleware/chat-webhook-body.js"; import { createChatWebhookDiagnostics } from "./services/chat-webhook-diagnostics.js"; @@ -483,6 +484,8 @@ export async function createApp( }, ) { const app = express(); + // First, so the reported server time includes admission and database waits. + app.use("/api", apiServerTiming()); app.use(databaseOperationMiddleware); app.use(idleAdmissionMiddleware); const staticUi = express.Router(); diff --git a/server/src/middleware/api-server-timing.ts b/server/src/middleware/api-server-timing.ts new file mode 100644 index 00000000000..29e04b07cb6 --- /dev/null +++ b/server/src/middleware/api-server-timing.ts @@ -0,0 +1,27 @@ +import type { RequestHandler, Response } from "express"; + +// Adds `paperclip_api;dur=` to every API response: the server time from +// request arrival until headers are written, including admission waits. Browser +// resource timing exposes it, so page-load investigations can tell server time +// from network and queueing time without traces. Route-specific phases (for +// example `paperclip_issue`) are preserved; this entry is appended after them. +// The header carries only a duration, never request or tenant data. +export const API_SERVER_TIMING_METRIC = "paperclip_api"; + +export function apiServerTiming(): RequestHandler { + return (_req, res, next) => { + const start = performance.now(); + const writeHead = res.writeHead as (...args: unknown[]) => Response; + res.writeHead = function writeHeadWithServerTiming(this: Response, ...args: unknown[]) { + if (!this.headersSent) appendServerTiming(this, `${API_SERVER_TIMING_METRIC};dur=${(performance.now() - start).toFixed(1)}`); + return writeHead.apply(this, args); + } as Response["writeHead"]; + next(); + }; +} + +function appendServerTiming(res: Response, entry: string) { + const existing = res.getHeader("Server-Timing"); + const values = existing === undefined ? [] : Array.isArray(existing) ? existing : [String(existing)]; + res.setHeader("Server-Timing", [...values, entry].join(", ")); +} diff --git a/tests/perf/issue-detail/README.md b/tests/perf/issue-detail/README.md index f121475c2fd..27069fa031f 100644 --- a/tests/perf/issue-detail/README.md +++ b/tests/perf/issue-detail/README.md @@ -50,6 +50,33 @@ harness validates the task identity before measuring. Network spans in the trace use recorded request start/end timestamps relative to task navigation; they include completed requests observed during the sample, even after content paint. +## Real-instance click harness + +Local fixtures cannot reproduce staging's network round trips, server contention +or object-store latency. `staging-click-harness.js` measures the same journey on +any running instance, including staging, from the signed-in browser: + +1. Open an Issues list, for example `//issues?view=mine`. +2. Paste the file into the DevTools console (or evaluate it through a browser + automation tool). +3. Run `await __taskOpenHarness.series(["ABC-1", "ABC-2", "ABC-3"])`. + +Each sample reports the time from the row click to a visible composer and to the +latest message in the viewport, the requests started before that point, the +requests that finished last before it (`releasedBy`), the slowest and repeated +requests, layout shifts, and any movement of the latest message after it first +appeared. `serverMs` comes from the `paperclip_api` Server-Timing entry that every +API response carries, so a long `duration` with a short `serverMs` points to the +network or browser queueing rather than the handler. A fetch that is still +running when the sample ends is listed with `pending: true`. Run samples +serially and record whether each task's data was already cached (a revisit) or +not. + +The summary labels each sample (`sample 1`, ...) instead of the task reference. +It replaces query values and every path segment that contains a digit with a +placeholder. Other path segments can stay, so review the output before you +share it outside the instance. + ## Task layout stability The normal browser CI suite also runs `tests/e2e/task-loading-frame.spec.ts`. diff --git a/tests/perf/issue-detail/staging-click-harness.js b/tests/perf/issue-detail/staging-click-harness.js new file mode 100644 index 00000000000..035a6264ccf --- /dev/null +++ b/tests/perf/issue-detail/staging-click-harness.js @@ -0,0 +1,182 @@ +// Task-open click harness for real instances (staging, production, local). +// +// Paste into DevTools (or run via a browser automation tool) on an Issues list +// page such as //issues?view=mine, then call: +// +// await __taskOpenHarness.measure("ABC-123") // click the row, time it +// await __taskOpenHarness.series(["ABC-1", "ABC-2"]) // back to the list between samples +// +// Each sample starts at the row click and records, on every animation frame: +// composerVisible the composer input is rendered and not concealed +// latestVisible the last conversation message is visible in the viewport +// threadMounted the chat thread element exists +// settled 3 s without the latest message changing, growing or moving +// plus layout shifts, moves of the latest message after it first appeared, and +// every API request started after the click with its server time (Server-Timing). +// A fetch that is still running when the sample ends is reported with +// `pending: true` and the time it has run so far. +// +// The summary labels each sample ("sample 1", ...) instead of the task +// reference. In request paths it replaces query values and every path segment +// that contains a digit (UUIDs, task references, numeric ids) with a +// placeholder. Review the output before you share it: other path segments, +// such as a company prefix, can stay. The harness reads only what the browser +// already received; nothing is sent. +(() => { + const visible = (el) => + Boolean(el && el.checkVisibility({ opacityProperty: true, visibilityProperty: true }) && el.getBoundingClientRect().height > 0); + const inViewport = (el) => { + const rect = el.getBoundingClientRect(); + return rect.bottom > 0 && rect.top < innerHeight && rect.height > 0; + }; + const scrub = (url) => { + const parsed = new URL(url, location.href); + const path = parsed.pathname + .split("/") + .map((segment) => (/\d/.test(segment) ? "" : segment)) + .join("/"); + const keys = [...parsed.searchParams.keys()]; + return keys.length > 0 ? `${path}?${keys.join("&")}` : path; + }; + const isApi = (url) => new URL(url, location.href).pathname.includes("/api/"); + const serverMs = (entry) => { + const metric = (entry.serverTiming || []).find((timing) => timing.name === "paperclip_api"); + return metric ? Math.round(metric.duration) : null; + }; + + let sampleCount = 0; + + async function measure(issueRef, { timeoutMs = 20_000, quietMs = 3_000, label } = {}) { + performance.setResourceTimingBufferSize(10_000); + const link = document.querySelector(`a[href$="/issues/${issueRef}"]`); + if (!link) throw new Error(`No visible row link for ${issueRef}`); + sampleCount += 1; + const sample = label ?? `sample ${sampleCount}`; + const shifts = []; + const observer = new PerformanceObserver((list) => { + for (const entry of list.getEntries()) if (!entry.hadRecentInput) shifts.push(entry); + }); + observer.observe({ type: "layout-shift", buffered: false }); + const marks = {}; + const latestChanges = []; + const latestMoves = []; + let latestKey = null; + let latestElement = null; + let latestTop = null; + // Resource Timing has no entry for a request that is still running, so + // record fetch starts too. In-flight fetches are reported as pending. + const fetches = []; + const originalFetch = window.fetch; + window.fetch = function (input, init) { + const url = typeof input === "string" ? input : input instanceof URL ? input.href : input.url; + const record = { url, start: performance.now(), done: false }; + fetches.push(record); + const result = originalFetch.call(this, input, init); + const finish = () => { + record.done = true; + }; + result.then(finish, finish); + return result; + }; + const t0 = performance.now(); + link.click(); + await new Promise((resolve) => { + const tick = () => { + const t = performance.now() - t0; + const thread = document.querySelector("[data-testid=task-chat-thread]"); + if (marks.threadMounted === undefined && thread) marks.threadMounted = t; + const composer = document.querySelector("[data-testid=task-chat-composer-input]"); + if (marks.composerVisible === undefined && visible(composer)) marks.composerVisible = t; + const messages = document.querySelectorAll("[data-conversation-message]"); + const latest = messages[messages.length - 1]; + if (latest && visible(latest) && inViewport(latest)) { + if (marks.latestVisible === undefined) marks.latestVisible = t; + // Text appended to a live message, or a message that grows in place, + // counts as a change, so `settled` waits for the output to stop. + const rect = latest.getBoundingClientRect(); + const text = latest.textContent || ""; + const key = `${messages.length}|${text.length}|${text.slice(-80)}|${Math.round(rect.height)}`; + if (key !== latestKey) { + latestChanges.push(Math.round(t)); + latestKey = key; + } + // Compare positions only for the same message element. A message + // that grows upward while the chat stays pinned to the bottom is a + // move; a different latest message starts a new position baseline. + if (latest !== latestElement) { + latestElement = latest; + latestTop = null; + } + const top = rect.top; + if (latestTop !== null && Math.abs(top - latestTop) > 2) latestMoves.push({ t: Math.round(t), dy: Math.round(top - latestTop) }); + latestTop = top; + } + const lastEvent = Math.max(latestChanges.at(-1) ?? 0, latestMoves.at(-1)?.t ?? 0); + if (marks.composerVisible !== undefined && marks.latestVisible !== undefined && t - lastEvent > quietMs) { + marks.settled = t; + return resolve(); + } + if (t > timeoutMs) return resolve(); + requestAnimationFrame(tick); + }; + requestAnimationFrame(tick); + }); + observer.disconnect(); + window.fetch = originalFetch; + const end = performance.now(); + const ready = Math.max(marks.composerVisible ?? Infinity, marks.latestVisible ?? Infinity); + const completed = performance + .getEntriesByType("resource") + .filter((entry) => entry.startTime >= t0 - 5 && isApi(entry.name)) + .map((entry) => ({ + url: scrub(entry.name), + start: Math.round(entry.startTime - t0), + duration: Math.round(entry.duration), + serverMs: serverMs(entry), + })); + const pending = fetches + .filter((record) => !record.done && isApi(record.url)) + .map((record) => ({ + url: scrub(record.url), + start: Math.round(record.start - t0), + duration: Math.round(end - record.start), + serverMs: null, + pending: true, + })); + const requests = [...completed, ...pending]; + const beforeReady = requests.filter((request) => request.start < ready); + const counts = {}; + for (const request of requests) counts[request.url] = (counts[request.url] ?? 0) + 1; + return { + sample, + marks: Object.fromEntries(Object.entries(marks).map(([key, value]) => [key, Math.round(value)])), + cls: Number(shifts.reduce((sum, entry) => sum + entry.value, 0).toFixed(4)), + latestMoves, + requests: { total: requests.length, beforeReady: beforeReady.length, pending: pending.length }, + // Requests that finished in the 250 ms before the page was ready. A + // request that finished after that point did not release the reveal. + releasedBy: completed + .filter((request) => request.start < ready) + .filter((request) => request.start + request.duration > ready - 250 && request.start + request.duration <= ready) + .sort((a, b) => b.start + b.duration - (a.start + a.duration)) + .slice(0, 3), + slowest: [...requests].sort((a, b) => b.duration - a.duration).slice(0, 5), + repeated: Object.entries(counts).filter(([, count]) => count > 1).map(([url, count]) => `${url} x${count}`), + }; + } + + async function series(issueRefs, options = {}) { + const listUrl = location.pathname + location.search; + const samples = []; + for (const issueRef of issueRefs) { + if (location.pathname + location.search !== listUrl) { + history.back(); + await new Promise((resolve) => setTimeout(resolve, options.listSettleMs ?? 3_000)); + } + samples.push(await measure(issueRef, options)); + } + return samples; + } + + window.__taskOpenHarness = { measure, series }; +})();