diff --git a/.claude/skills/indexing-diagnostics/SKILL.md b/.claude/skills/indexing-diagnostics/SKILL.md index 6b2587e4e8..8670499adb 100644 --- a/.claude/skills/indexing-diagnostics/SKILL.md +++ b/.claude/skills/indexing-diagnostics/SKILL.md @@ -1,6 +1,6 @@ --- name: indexing-diagnostics -description: Investigate slow or failing indexing using the per-row diagnostics persisted split by visit — the index visit's breakdown on `boxel_index.diagnostics`, the prerender-html visit's render breakdown (launch/wait/render timings, per-format render timings) on `prerendered_html.diagnostics`, each mirrored onto its table's `error_doc.diagnostics` for error rows, joinable per row via url + the two request ids — plus the matching prerender-server / manager logs. Covers (1) a render inside indexing timed out — classify which part of the prerender pipeline stalled, (2) an incremental or full reindex was slow but didn't fail — attribute time across the invalidation fan-out and find the rows that cost the most, (3) enumerating cards with broken `linksTo` / `linksToMany` targets via `diagnostics.brokenLinks` (those cards index cleanly, so this is the only indexed signal), (4) verifying the module pre-warm phase populates the definition cache under a key the indexer / on-demand prerender reads actually hit — i.e. it isn't a silent no-op — via the `definition-cache-key` hit/miss log channel, and (5) attributing a slow in-render `_search` round-trip to the realm-server's own request→response stages (parse / SQL / loadLinks / serialize / queue) via the `realm:search-timing`, `realm:requests` (`dur=`), and `realm:health` log channels keyed by the `x-boxel-logging-correlation-id` correlation id, and (6) capturing full CPU profiles / CDP traces / heap-allocation profiles to the prerender S3 artifact bucket (`boxel-prerender-artifacts-`) when the summary signals name a hot function but you need the whole call tree, a JS-vs-GC-vs-layout breakdown, or a heap-growth story — the streaming trace is the only capture that survives a fully-wedged renderer; gated behind `PRERENDER_PROFILE_AFFINITY` + per-mode SSM flags and pulled with the `boxel-claude-readonly` S3 read grant. Use when indexing fails with "Render timeout", when a user sees a 504, when a reindex took much longer than expected, when an `.gts` edit triggers a surprising amount of re-render work, when investigating the CS-10820 saturation class of incidents, when a render stalls in `waiting-stability` on a `_search` whose SQL is fast but whose response is slow to come back, or when asked to list / count cards with broken links in a realm. For staging/prod investigations this skill layers on top of `aws-access`, which provides the AWS session and the SSM port-forward path into the in-VPC database (authenticated as `claude_readonly_user`) — read that skill first when the question is about a deployed environment. +description: Investigate slow or failing indexing using the per-row diagnostics persisted split by visit — the index visit's breakdown on `boxel_index.diagnostics`, the prerender-html visit's render breakdown (launch/wait/render timings, per-format render timings) on `prerendered_html.diagnostics`, each mirrored onto its table's `error_doc.diagnostics` for error rows, joinable per row via url + the two request ids — plus the matching prerender-server / manager logs. Covers (1) a render inside indexing timed out — classify which part of the prerender pipeline stalled, (2) an incremental or full reindex was slow but didn't fail — attribute time across the invalidation fan-out and find the rows that cost the most, (3) enumerating cards with broken `linksTo` / `linksToMany` targets via `diagnostics.brokenLinks` (those cards index cleanly, so this is the only indexed signal), (4) verifying the module pre-warm phase populates the definition cache under a key the indexer / on-demand prerender reads actually hit — i.e. it isn't a silent no-op — via the `definition-cache-key` hit/miss log channel, and (5) attributing a slow in-render `_search` round-trip to the realm-server's own request→response stages (parse / SQL / loadLinks / serialize / queue) via the `realm:search-timing`, `realm:requests` (`dur=`), and `realm:health` log channels keyed by the `x-boxel-logging-correlation-id` correlation id, and (6) capturing full CPU profiles / CDP traces / heap-allocation profiles to the prerender S3 artifact bucket (`boxel-prerender-artifacts-`) when the summary signals name a hot function but you need the whole call tree, a JS-vs-GC-vs-layout breakdown, or a heap-growth story — the streaming trace is the only capture that survives a fully-wedged renderer; gated behind `PRERENDER_PROFILE_AFFINITY` + per-mode SSM flags and pulled with the `boxel-claude-readonly` S3 read grant, and (7) attributing a slow search-doc build to specific fields and link loads — the settle loop's per-target load timings (`searchDocSettleMs` / `searchDocLinkLoads`) vs the field walk's per-dotted-path evaluation timings (`searchDocMs` / `searchDocFieldsMs`), both on `boxel_index.diagnostics`. Use when indexing fails with "Render timeout", when a user sees a 504, when a reindex took much longer than expected, when an `.gts` edit triggers a surprising amount of re-render work, when investigating prerender-saturation incidents, when a render stalls in `waiting-stability` on a `_search` whose SQL is fast but whose response is slow to come back, when a row's index visit is slow and you need to know which field or link load inside the search doc ate the time, or when asked to list / count cards with broken links in a realm. For staging/prod investigations this skill layers on top of `aws-access`, which provides the AWS session and the SSM port-forward path into the in-VPC database (authenticated as `claude_readonly_user`) — read that skill first when the question is about a deployed environment. allowed-tools: Read, Grep, Glob, Bash --- @@ -13,6 +13,7 @@ Every indexer write (`IndexWriter.updateEntry`) persists a diagnostic blob on th - **Which cards have broken links** — enumerate cards with a broken `linksTo` / `linksToMany` target straight from the column; those cards index cleanly, so `diagnostics.brokenLinks` is the only indexed signal. See [Mode E](#mode-e--enumerate-cards-with-broken-links). - **Whether module pre-warm is effective** — confirm the pre-warm phase populates the definition cache under a key the indexer / on-demand reads actually hit (not a silent no-op), using the `definition-cache-key` hit/miss log channel. This one isn't about the `diagnostics` column — it reads the logs. See [Mode F](#mode-f--module-pre-warm-and-definition-cache-hitmiss). - **Why an in-render `_search` was slow to come back** — when a render stalls in `waiting-stability` waiting on a query-backed `linksTo` / `linksToMany` search (the `boxel_index.diagnostics` shows it client-side as `queryLoadsInFlight` aging) but the SQL is fast, attribute the realm-server's request→response time across its stages (parse / SQL / loadLinks / serialize) and tell handler-time from queued-before-handler / event-loop saturation. Log-based, keyed by the correlation id. See [Mode G](#mode-g--an-in-render-_search-was-slow-server-side-search-timing). +- **A search doc that was slow to build** — attribute a slow index visit inside the search-doc build itself: the settle loop's link loads (`searchDocSettleMs`, per target in `searchDocLinkLoads`) vs the field walk (`searchDocMs`, per dotted field path in `searchDocFieldsMs`). See [Mode J](#mode-j--a-search-doc-was-slow-to-build-per-field--per-link-attribution). The first three read from the same `diagnostics` column; the difference is the query you start with. Modes F and G are log-based. @@ -20,7 +21,7 @@ The first three read from the same `diagnostics` column; the difference is the q Six places, all correlated: -1. **`boxel_index.diagnostics` (and `boxel_index_working.diagnostics`)** — JSONB column, populated for **every** row the indexer writes, regardless of `has_error`. Source of truth for the **index visit** of a card/file: the `RenderTimeoutDiagnostics` server timings of that visit plus the host-side `PrerenderMetaDiagnostics` block (`serializeMs`, `searchDocMs`, `computedCalls`/`computedCacheHits`) and three write-side stamps: `invalidationId`, `indexedAt`, `requestId`. It also carries a `brokenLinks` array on any card row whose render found a broken `linksTo` / `linksToMany` target — see [Mode E](#mode-e--enumerate-cards-with-broken-links). Note this is the one block that isn't about _timing_: a card with broken links still indexes as a clean `type='instance'` (the broken slot renders a placeholder), so `brokenLinks` is the only indexed signal that the row has a broken reference. Rows written by a fused single-visit pass (the SQLite in-browser path) carry one **combined** blob covering both visits here instead. +1. **`boxel_index.diagnostics` (and `boxel_index_working.diagnostics`)** — JSONB column, populated for **every** row the indexer writes, regardless of `has_error`. Source of truth for the **index visit** of a card/file: the `RenderTimeoutDiagnostics` server timings of that visit plus the host-side `PrerenderMetaDiagnostics` block (`serializeMs`, `searchDocMs`, `searchDocSettleMs`/`searchDocSettlePasses`, `searchDocFieldsMs`, `searchDocLinkLoads`, `computedCalls`/`computedCacheHits`) and three write-side stamps: `invalidationId`, `indexedAt`, `requestId`. It also carries a `brokenLinks` array on any card row whose render found a broken `linksTo` / `linksToMany` target — see [Mode E](#mode-e--enumerate-cards-with-broken-links). Note this is the one block that isn't about _timing_: a card with broken links still indexes as a clean `type='instance'` (the broken slot renders a placeholder), so `brokenLinks` is the only indexed signal that the row has a broken reference. Rows written by a fused single-visit pass (the SQLite in-browser path) carry one **combined** blob covering both visits here instead. 2. **`prerendered_html.diagnostics` (and `prerendered_html_working.diagnostics`)** — JSONB column, populated for every row the `prerender_html` job writes, success and render-error alike. Source of truth for the **prerender-html visit**: launch/wait timings, `renderElapsedMs`/`totalElapsedMs`, the per-format `renderFormatsMs` breakdown, and the visit's HTTP correlation id under `prerenderHtmlRequestId` (never `requestId` — that name always means an index visit). See [Two visits, two tables](#two-visits-two-tables--which-timings-live-where). 3. **`modules.diagnostics`** — JSONB column, populated for every row `persistModuleCacheEntry` writes (success and error paths). Source of truth for **module** renders (`prerenderModule` → definition extraction). Same `RenderTimeoutDiagnostics` shape with `requestId` flattened in; no `invalidationId` (modules don't go through `Batch.invalidate`). The row's existing `created_at` column is the wall-clock stamp for cross-table joins. See [Mode D](#mode-d--a-module-render-was-slow-or-hung) below. 4. **`error_doc.diagnostics`** — derived copy of the same table's `diagnostics`, written only for error rows: an index error's copy rides `boxel_index.error_doc`, a render error's rides `prerendered_html.error_doc` (an instance's effective error is the union of the two). Exists so the existing UI read path (`error_doc` → `CardErrorJSONAPI.meta.diagnostics` via `formattedError`) keeps working without a schema rename. Non-error rows have `error_doc = null`; go to `diagnostics` directly. @@ -42,10 +43,10 @@ When wrapping a query below into the staging/prod form, run it through the `psql A URL is produced by two prerender visits on two channels, and each visit's diagnostics follow its writes: -| where | visit | what's in it | -| ------------------------------ | -------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | -| `boxel_index.diagnostics` | index visit | that visit's server timings (`launchMs`, `waits`, `renderElapsedMs`, `totalElapsedMs`), the search-doc build (`serializeMs`, `searchDocMs`, `computedCalls`/`computedCacheHits`), `brokenLinks`, and the write-side stamps (`invalidationId`, `indexedAt`). HTTP id: `requestId`. | -| `prerendered_html.diagnostics` | prerender-html visit | that visit's server timings (`launchMs`, `waits`, `renderElapsedMs`, `totalElapsedMs`) plus `renderFormatsMs` — per-format wall-clock, split into a `card` and a `file` block with one number per html-route step (`isolated`, `head`, `atom`, `markdown`, `fitted`, `embedded`; the ancestor-driven `fitted`/`embedded` numbers each cover the whole ancestor chain). HTTP id: `prerenderHtmlRequestId`. | +| where | visit | what's in it | +| ------------------------------ | -------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `boxel_index.diagnostics` | index visit | that visit's server timings (`launchMs`, `waits`, `renderElapsedMs`, `totalElapsedMs`), the search-doc build (`serializeMs`, `searchDocMs`, `searchDocSettleMs`/`searchDocSettlePasses`, the per-field `searchDocFieldsMs` and per-link-load `searchDocLinkLoads` detail, `computedCalls`/`computedCacheHits`), `brokenLinks`, and the write-side stamps (`invalidationId`, `indexedAt`). HTTP id: `requestId`. | +| `prerendered_html.diagnostics` | prerender-html visit | that visit's server timings (`launchMs`, `waits`, `renderElapsedMs`, `totalElapsedMs`) plus `renderFormatsMs` — per-format wall-clock, split into a `card` and a `file` block with one number per html-route step (`isolated`, `head`, `atom`, `markdown`, `fitted`, `embedded`; the ancestor-driven `fitted`/`embedded` numbers each cover the whole ancestor chain). HTTP id: `prerenderHtmlRequestId`. | So "why was indexing this card slow?" and "why was rendering this card slow?" are separately answerable per row: the index cost is `boxel_index.diagnostics`, the render cost is `prerendered_html.diagnostics`, and inside the render cost `renderFormatsMs` names the format that dominated (a slow `isolated` template vs a `fitted` render fanning out across many ancestors). @@ -223,6 +224,7 @@ SELECT (diagnostics->>'computedCacheHits')::int AS cache_hits, (diagnostics->>'serializeMs')::numeric AS serialize_ms, (diagnostics->>'searchDocMs')::numeric AS search_doc_ms, + (diagnostics->>'searchDocSettleMs')::numeric AS settle_ms, (diagnostics->>'renderElapsedMs')::int AS render_ms FROM boxel_index WHERE realm_url = 'https://localhost:4201/user/your-realm/' @@ -231,6 +233,8 @@ ORDER BY (diagnostics->>'computedCalls')::int DESC NULLS LAST LIMIT 20; ``` +For any row this surfaces, [Mode J](#mode-j--a-search-doc-was-slow-to-build-per-field--per-link-attribution) drills inside its search-doc cost — which field, which link load. + ## Mode C — a worker job is stuck or got rejected Mode A and Mode B both assume `boxel_index` has up-to-date `diagnostics` for the rows you're investigating. That assumption breaks when an indexing job is _in progress_ or got rejected mid-flight: nothing has been committed to `boxel_index` yet (the indexer writes to a staging table and only swaps on success — see [Reading partial progress from `boxel_index_working`](#5-reading-partial-progress-from-boxel_index_working) below), so the diagnostics column there is stale or null for the affected rows. @@ -1047,6 +1051,89 @@ Lines are FireLens-wrapped (`{"log":"…"}`); pull `.log`. Strip everything afte - If `pausedStack` is starved AND `--prof` shows the time in opaque native frames with no JS attribution, the peg is inside a native builtin — the frame names it, but the _why_ needs reading that builtin's inputs (e.g. a pathological regex / string). - It's a CPU-peg mode. A render that's idle-waiting (`mainThreadResponsive=true`, `cpuTopFrames (idle)`, a long-pending fetch) is a **data stall** — Mode A's `pendingFetches` / Mode G, not this. +## Mode J — a search doc was slow to build (per-field / per-link attribution) + +The index visit's cost is dominated by search-doc assembly, and its diagnostics split that assembly into two disjoint phases, each with per-item detail: + +1. **The settle loop** (`searchDocSettleMs`, `searchDocSettlePasses`) — the passes that drive the card's searchable-path link loads (and the links its contained/computed fields read) to quiescence. This is where link targets actually load; the per-target breakdown is `searchDocLinkLoads` (`{ path, target, ms }`, dotted `linksTo`/`linksToMany` field path + loaded URL). +2. **The timed searchDoc walk** (`searchDocMs`) — evaluation of the card's fields against the now-settled store. The per-field breakdown is `searchDocFieldsMs`, keyed by dotted field path with **inclusive** times (a parent includes its children, so the keys read as a drill-down to the slow leaf). + +Both detail blocks are bounded — the slowest 20 entries at ≥ 1 ms — so a typical ~1 ms search doc persists neither, and their absence on a slow row is itself a signal (see step 3). + +**Step 1 — find the rows whose search-doc build dominates.** + +```sql +SELECT + url, + (diagnostics->>'searchDocSettleMs')::numeric AS settle_ms, + (diagnostics->>'searchDocSettlePasses')::int AS passes, + (diagnostics->>'searchDocMs')::numeric AS search_doc_ms, + (diagnostics->>'serializeMs')::numeric AS serialize_ms, + (diagnostics->>'renderElapsedMs')::int AS render_ms +FROM boxel_index +WHERE realm_url = 'https://localhost:4201/user/your-realm/' + AND diagnostics->>'searchDocSettleMs' IS NOT NULL +ORDER BY (diagnostics->>'searchDocSettleMs')::numeric + + (diagnostics->>'searchDocMs')::numeric DESC NULLS LAST +LIMIT 20; +``` + +`settle_ms + search_doc_ms` ≈ the row's search-doc production cost. Which of the two dominates picks the next step: settle-dominated → step 2 (loads), searchDoc-dominated → step 3 (fields). + +**Step 2 — settle-dominated: which link loads were slow.** + +```sql +-- Fan out the per-load entries for one row, slowest first. +SELECT + ll->>'path' AS field_path, + ll->>'target' AS target_url, + (ll->>'ms')::numeric AS ms +FROM boxel_index i +CROSS JOIN LATERAL jsonb_array_elements(i.diagnostics->'searchDocLinkLoads') AS ll +WHERE i.url = '' AND i.type = 'instance' +ORDER BY ms DESC; + +-- Or realm-wide: which TARGETS are slow to load across many owners' +-- search docs (one slow shared card taxes every card that makes it +-- searchable). +SELECT + ll->>'target' AS target_url, + count(*) AS owners, + max((ll->>'ms')::numeric) AS worst_ms, + avg((ll->>'ms')::numeric) AS avg_ms +FROM boxel_index i +CROSS JOIN LATERAL jsonb_array_elements(i.diagnostics->'searchDocLinkLoads') AS ll +WHERE i.realm_url = 'https://localhost:4201/user/your-realm/' +GROUP BY 1 +ORDER BY worst_ms DESC +LIMIT 20; +``` + +Read the shape: one very slow entry = one slow target (a cross-realm link? a target whose own realm is slow? — Mode G if the load is a `_search`-backed path, the target realm's own logs otherwise); many moderate entries under one `path` = a wide `linksToMany` route fanning out (is that `searchable` depth actually needed?). An entry with an **empty `path`** is a load a field getter fired — a computed reading a link — so the fix target is the computed that reads that URL, not a `searchable` annotation. A high `passes` count with moderate per-load times means a deep chain — each pass unlocks one more hop, so depth costs serial round-trips even when each load is fine. + +**Step 3 — searchDoc-dominated: which fields were expensive to evaluate.** + +```sql +-- Hot fields for one row, slowest first. Keys are dotted paths from the +-- indexed card's root; a parent's time includes its children's, so read +-- the deepest hot key as the culprit and its ancestors as the route to it. +SELECT key AS field_path, value::numeric AS ms +FROM boxel_index i +CROSS JOIN LATERAL jsonb_each_text(i.diagnostics->'searchDocFieldsMs') +WHERE i.url = '' AND i.type = 'instance' +ORDER BY value::numeric DESC; +``` + +Cross-check against `searchDocLinkLoads`: a hot field path **with** a matching load entry was waiting on the load (fix the load); a hot field path **without** one was expensive to compute — a `computeVia` doing real work per read (correlate with `computedCalls`, and see the computed-field-hot-path row in [Classify in one pass](#classify-in-one-pass)). + +A large `searchDocMs` with **no** `searchDocFieldsMs` entries means no single field crossed the 1 ms floor — death by a thousand cheap fields (very wide cards, big containsMany arrays) rather than one hot path. That's a card-shape problem, not a single-field bug. + +### What Mode J can't tell you + +- **Nothing below the field grain.** A hot leaf field's time is one number; profiling inside its `computeVia` is Mode H territory. +- **A row can predate the instrumentation.** A row whose producing host build didn't emit these fields carries none of them; absence means "not measured", not "fast". Check `indexedAt` against when the realm was last reindexed. +- **The bounded lists drop the tail.** Entries below the floor (or beyond the slowest 20) aren't persisted; the aggregates (`searchDocSettleMs`, `searchDocMs`) still carry the total, so the un-itemized remainder is the difference. + ## Field-by-field reading `diagnostics` carries `RenderTimeoutDiagnostics` (defined in `packages/runtime-common/index.ts`) plus `invalidationId` / `indexedAt` / `requestId`. Every render-side field is optional — absent means the hook wasn't available in that build or the page died before the capture could read it. @@ -1175,13 +1262,52 @@ Lines are FireLens-wrapped (`{"log":"…"}`); pull `.log`. Strip everything afte // contains-many / links-to field does this). "serializeMs": 42.1, // host-side wall-clock of `serializeCard(instance, { // includeComputeds: true })` for this card. - "searchDocMs": 18.3 // host-side wall-clock of `searchDoc(instance)` for + "searchDocMs": 18.3, // host-side wall-clock of `searchDoc(instance)` for // this card. Sum with `serializeMs` to get the host's // contribution to `renderElapsedMs`. Pairs with // `computedCalls` so you can normalize: a card with // `computedCalls=500, searchDocMs=80` is ~6 calls/ms // — a sign of a hot compute that may be worth a // dependency-aware skip. + "searchDocSettleMs": 812.4, // host-side wall-clock of the searchable load-settle + // loop that runs BEFORE the timed searchDoc walk. This + // is where the card's searchable link targets actually + // load — by the time `searchDocMs` is measured they're + // resident — so link-load cost lives here, not inside + // `searchDocMs`. Attributed per target by + // `searchDocLinkLoads`. + "searchDocSettlePasses": 3, // settle passes until the store's load generation held + // steady. Each pass loads one more dependency-depth + // wave (a deeper searchable hop, a computed's link), so + // a high count = a deep link/computed chain. Capped at + // 20 (a warning is logged at the cap). + "searchDocFieldsMs": { // per-field inclusive evaluation timings from the timed + // searchDoc walk, keyed by dotted field path from the + // indexed card's root. A parent's time includes its + // children's, so the drill-down to the slow leaf reads + // straight off the keys. Bounded: slowest 20 fields at + // >= 1 ms; a typical ~1 ms search doc records nothing. + // A large `searchDocMs` with NO entries = death by a + // thousand cheap fields, not one hot path. + "policies": 14.2, + "policies.premiumTotal": 13.8 + }, + "searchDocLinkLoads": [ // slowest link-target loads performed while producing + // this row's search doc (settle passes + any the timed + // walk still did). `path` = the dotted linksTo / + // linksToMany field path; `target` = the loaded URL (a + // linksToMany records one entry per slot, same path, + // different target). A load fired through a field + // getter — a computed reading a link — carries an + // empty path: the target and cost are attributed, the + // owning field isn't nameable there. Same bounding as + // `searchDocFieldsMs`. Separates "linked instance slow + // to load" (an entry here) from "field expensive to + // compute" (a hot `searchDocFieldsMs` path with no + // matching load entry). + { "path": "author", "target": "https://realm.example/Author/1", "ms": 640.1 }, + { "path": "", "target": "https://realm.example/Publisher/2", "ms": 210.4 } + ] } ``` @@ -1199,6 +1325,7 @@ All ms values are server-observed walltime. - `cardDocLoadsInFlight[*].ageMs` / `fileMetaDocLoadsInFlight[*].ageMs` mirror the query version for linked-field (card doc) / file-meta loads. One URL with a very large `ageMs` = one slow linksTo target; many URLs with small `ageMs` = fan-out. - `recentCardDocLoads[*].ms` / `recentFileMetaLoads[*].ms` are the completed-load histories; same usage as `recentQueryLoads`. - `computedCalls` + `computedCacheHits` together represent total compute pressure on the render.meta pass. The split tells you how much duplicate work the pass-scoped memo absorbed — a 1:0 ratio means every field was read once, a 1:5 ratio means the cards re-read each computed five extra times (typical for cards where many sibling fields share a computed input). `searchDocMs` + `serializeMs` are the host's contribution to `renderElapsedMs`; comparing `computedCalls / (searchDocMs + serializeMs)` across cards finds the slow-per-call computes that are worth profiling. +- `searchDocSettleMs` is disjoint from `searchDocMs`: the settle loop runs first and performs the link loads; the timed searchDoc walk then runs against a settled store. So "producing this row's search doc" cost ≈ `searchDocSettleMs + searchDocMs`, and a slow row splits cleanly: settle-dominated → loading (read `searchDocLinkLoads` for which target), searchDoc-dominated → evaluation (read `searchDocFieldsMs` for which field). The retained `searchDocFieldsMs` entries are inclusive-time dotted paths — the top-level entries (no dot) sum to ≈ `searchDocMs` on a hot-path card; the deeper keys under a hot top-level key are the drill-down, not additional cost. Keep the field names in lock-step with the type in `packages/runtime-common/index.ts`. @@ -1221,7 +1348,8 @@ Walk the fields top-down. The _first_ positive signal wins; stop there. | `renderStage` = `waiting-stability` with empty in-flight arrays | **Render stall** | Nothing is loading but settlement never finishes. Classic Glimmer tracking loop — template is invalidating itself. `capturedDom` usually shows the partially-rendered component. `blockedTimerSummary` will list swallowed timers that may hint at a scheduling loop. | | `currentlyEvaluatingModule` non-null, or `stageAgeMs` large with empty in-flight arrays | **Synchronous browser stall (typically Glimmer compile during module eval)** | `recentModuleEvaluations` shows the worst offenders. A single URL with `ms > 5000` usually means "this module has a giant template that takes forever to compile". Many small entries (say 50+ at 100–500 ms each) summing into the stall budget mean card fan-out where each dependent card contributes a compile. Split the module, lazy-load the template, or reduce the component fan-out. | | `blockedTimerSummary` populated | **Supplementary** | Tells you which timer-driven code is fighting the render. Not a root cause on its own. | -| `computedCalls` large (e.g. > 1000) AND `searchDocMs + serializeMs` ≈ `renderElapsedMs` | **Computed-field hot path** | The render.meta traversal itself is the bottleneck, not data loads or browser stalls. Look at `computedCalls / (searchDocMs + serializeMs)` — > ~5 calls/ms is fast, < ~1 call/ms means a few slow `computeVia` functions dominate. Inspect the card class for aggregate computeds that scan a `linksToMany` relation on every read (Portfolio-over-Policies style) and consider hoisting the scan into a shared rollup or adding `computeDeps` so the field can be skipped when its inputs don't change. The pass-scoped memo already eliminates duplicate reads in one traversal (visible in `computedCacheHits`); further wins require structural changes to the card. | +| `computedCalls` large (e.g. > 1000) AND `searchDocMs + serializeMs` ≈ `renderElapsedMs` | **Computed-field hot path** | The render.meta traversal itself is the bottleneck, not data loads or browser stalls. Look at `computedCalls / (searchDocMs + serializeMs)` — > ~5 calls/ms is fast, < ~1 call/ms means a few slow `computeVia` functions dominate. `searchDocFieldsMs` names the field: its dotted-path keys rank the walk's hot paths, so instead of inspecting the card class blind you start at the top entry (see [Mode J](#mode-j--a-search-doc-was-slow-to-build-per-field--per-link-attribution)). Consider hoisting an aggregate computed's scan into a shared rollup or adding `computeDeps` so the field can be skipped when its inputs don't change. The pass-scoped memo already eliminates duplicate reads in one traversal (visible in `computedCacheHits`); further wins require structural changes to the card. | +| `searchDocSettleMs` large (≫ `searchDocMs`) | **Search-doc link-load stall** | The index visit spent its time loading the card's searchable link targets, not evaluating fields. `searchDocLinkLoads` names the slow target(s) per dotted field path — one very slow entry is one slow linksTo target (is its realm slow? cross-realm?); many moderate entries are a fan-out (a wide `linksToMany` route — consider whether the `searchable` annotation needs that depth). A high `searchDocSettlePasses` alongside means a deep chain: each pass unlocks one more hop. See [Mode J](#mode-j--a-search-doc-was-slow-to-build-per-field--per-link-attribution). | ### Special cases diff --git a/packages/base/searchable.ts b/packages/base/searchable.ts index e3ceb6fd70..f3bb64ffe1 100644 --- a/packages/base/searchable.ts +++ b/packages/base/searchable.ts @@ -6,6 +6,7 @@ import { primitive, relativeTo, routesForField, + type SearchDocTimings, type SerializedError, } from '@cardstack/runtime-common'; import { @@ -56,6 +57,12 @@ export async function searchDocFromFields( // owner — whether or not the render happened to load it (a `{ id }`-only link // contributes none, since its target's data is not in the doc). dependencies: Set = new Set(), + // Optional timing collector, filled in place as the walk runs (so entries + // recorded before a mid-walk throw survive): per-field inclusive + // evaluation wall-clock keyed by dotted path, and one entry per link- + // target load performed. Each sub-collector is opt-in and raw — the + // caller bounds and rounds before persisting. + timings?: SearchDocTimings, ): Promise> { let routes = seedSearchableRoutes( instance.constructor as unknown as typeof BaseDef, @@ -67,6 +74,8 @@ export async function searchDocFromFields( [], getStore(instance), dependencies, + '', + timings, )) as Record; } @@ -167,6 +176,10 @@ async function searchableQueryableValue( // must still load against the owner's store. store: CardStore, dependencies: Set, + // Dotted field path from the indexed card's root down to `value` ('' at + // the root); keys the `timings` entries. + path: string, + timings: SearchDocTimings | undefined, ): Promise { if (primitive in fieldCard) { // Delegate to the field's own queryableValue. The default handles @@ -216,6 +229,13 @@ async function searchableQueryableValue( let isDeclaredLink = (field!.fieldType === 'linksTo' || field!.fieldType === 'linksToMany') && !field!.computeVia; + let fieldPath = path === '' ? fieldName : `${path}.${fieldName}`; + // Inclusive per-field timing: starts before the field read — a + // computed's computeVia runs inside peekAtField — and covers the nested + // recursion and link loads below, so a slow leaf surfaces together with + // every ancestor on its path. Guarded on the collector so an + // uninstrumented walk pays no timer calls. + let fieldStart = timings?.fieldsMs ? performance.now() : 0; let rawValue = isDeclaredLink && !getDataBucket(value).has(fieldName) ? null @@ -231,6 +251,8 @@ async function searchableQueryableValue( nextStack, store, dependencies, + fieldPath, + timings, ), ]); break; @@ -255,6 +277,8 @@ async function searchableQueryableValue( nextStack, store, dependencies, + fieldPath, + timings, ); if (v != null) { items.push(v); @@ -276,6 +300,8 @@ async function searchableQueryableValue( store, makeAbsoluteURL, dependencies, + fieldPath, + timings, ), ]); break; @@ -292,11 +318,19 @@ async function searchableQueryableValue( store, makeAbsoluteURL, dependencies, + fieldPath, + timings, ), ]); break; } } + if (timings?.fieldsMs) { + // Accumulate rather than assign: a plural field's items (and a card + // re-entered on another branch) all land under one path key. + timings.fieldsMs[fieldPath] = + (timings.fieldsMs[fieldPath] ?? 0) + (performance.now() - fieldStart); + } } return Object.fromEntries(entries); } @@ -314,6 +348,8 @@ async function searchableLink( store: CardStore, makeAbsoluteURL: (reference: string) => string, dependencies: Set, + path: string, + timings: SearchDocTimings | undefined, ): Promise { if (rawValue == null) { return null; @@ -347,7 +383,13 @@ async function searchableLink( // getter. The store can't `toURL` a relative string, which would otherwise // degrade an expandable searchable link to `{ id }`. let resolvedRef = makeAbsoluteURL(rawValue.reference); + let loadStart = timings?.linkLoads ? performance.now() : 0; let result = await loadSearchableTarget(store, resolvedRef); + timings?.linkLoads?.push({ + path, + target: resolvedRef, + ms: performance.now() - loadStart, + }); if (result.status === 'broken') { // Plant the terminal sentinel on the owner's field so `getBrokenLinks` // (which reads terminal sentinels from the data bucket) records this @@ -374,6 +416,8 @@ async function searchableLink( stack, store, dependencies, + path, + timings, ); } @@ -390,6 +434,8 @@ async function searchableLinksToMany( store: CardStore, makeAbsoluteURL: (reference: string) => string, dependencies: Set, + path: string, + timings: SearchDocTimings | undefined, ): Promise { // A whole-field sentinel (errored/unresolved plural) is not iterable; treat // as empty, same as `LinksToMany.queryableValue`. @@ -423,7 +469,13 @@ async function searchableLinksToMany( if (isNotLoadedValue(item)) { // Resolve a relative reference before the load — see `searchableLink`. let resolvedRef = makeAbsoluteURL(item.reference); + let loadStart = timings?.linkLoads ? performance.now() : 0; let result = await loadSearchableTarget(store, resolvedRef); + timings?.linkLoads?.push({ + path, + target: resolvedRef, + ms: performance.now() - loadStart, + }); if (result.status === 'broken') { // Plant the sentinel into the failed slot so `getBrokenLinks` records // this broken searchable element (see `searchableLink`). Assign through @@ -449,6 +501,8 @@ async function searchableLinksToMany( stack, store, dependencies, + path, + timings, ); if (expanded != null) { out.push( diff --git a/packages/host/app/routes/render/meta.ts b/packages/host/app/routes/render/meta.ts index 76a427af5f..ff1dd7b186 100644 --- a/packages/host/app/routes/render/meta.ts +++ b/packages/host/app/routes/render/meta.ts @@ -15,6 +15,8 @@ import { relationshipEntries, realmURL, snapshotRuntimeDependencies, + type SearchDocLinkLoad, + type SearchDocTimings, type SingleCardDocument, type PrerenderMeta, type PrerenderMetaDiagnostics, @@ -46,6 +48,77 @@ const computePerfLog = logger('host:computed-perf'); const SEARCHABLE_SETTLE_MAX_PASSES = 20; const SEARCHABLE_SETTLE_REQUIRED_STABLE_PASSES = 2; +// Persistence bounds for the per-field / per-link-load search-doc timings. +// The raw collectors are unbounded; only the slowest entries at/over the +// floor land on the row, so a typical ~1 ms search doc records nothing and +// a wide card can't bloat its diagnostics blob. +const SEARCH_DOC_TIMING_FLOOR_MS = 1; +const SEARCH_DOC_TIMING_MAX_ENTRIES = 20; + +const roundMs = (ms: number) => Math.round(ms * 100) / 100; + +// Slowest-N-at/over-the-floor pruning for the per-field timings. Rank by +// value when reading — jsonb normalizes key order, so the persisted object +// carries no ordering. An ancestor's inclusive time is >= any descendant's, +// so a kept entry's parent chain makes the cut with it (barring an +// exact-tie at the cut-off). +function pruneSearchDocFieldsMs( + fieldsMs: Record, +): Record | undefined { + let kept = Object.entries(fieldsMs) + .filter(([, ms]) => ms >= SEARCH_DOC_TIMING_FLOOR_MS) + .sort(([, a], [, b]) => b - a) + .slice(0, SEARCH_DOC_TIMING_MAX_ENTRIES); + return kept.length > 0 + ? Object.fromEntries(kept.map(([path, ms]) => [path, roundMs(ms)])) + : undefined; +} + +// Same pruning for link-target loads. The floor also drops the near-zero +// entries recorded when a target was already resident in the store, so what +// survives is the loads that actually cost something. +function pruneSearchDocLinkLoads( + linkLoads: SearchDocLinkLoad[], +): SearchDocLinkLoad[] | undefined { + let kept = linkLoads + .filter(({ ms }) => ms >= SEARCH_DOC_TIMING_FLOOR_MS) + .sort((a, b) => b.ms - a.ms) + .slice(0, SEARCH_DOC_TIMING_MAX_ENTRIES) + .map((load) => ({ ...load, ms: roundMs(load.ms) })); + return kept.length > 0 ? kept : undefined; +} + +// Multiset diff over the store's bounded completed-load histories: the +// entries present in `after` beyond their multiplicity in `before`. Used to +// attribute loads the settle loop fired through field getters (a computed +// reading a link loads via `lazilyLoadLink`, not via the generator's +// targeted loading) — those loads land in the store's history but never +// pass through the generator's collector. The histories keep only the +// slowest entries, so a load evicted by slower siblings goes unreported; +// what survives is by construction the part worth attributing. Exported for +// unit testing. +export function newLoadEntries( + before: Array<{ url: string; ms: number }>, + after: Array<{ url: string; ms: number }>, +): Array<{ url: string; ms: number }> { + let seen = new Map(); + for (let { url, ms } of before) { + let key = `${url}|${ms}`; + seen.set(key, (seen.get(key) ?? 0) + 1); + } + let fresh: Array<{ url: string; ms: number }> = []; + for (let entry of after) { + let key = `${entry.url}|${entry.ms}`; + let count = seen.get(key) ?? 0; + if (count > 0) { + seen.set(key, count - 1); + } else { + fresh.push(entry); + } + } + return fresh; +} + // The base module whose generator produces every search doc. Recorded as a // dependency of the meta output directly (see the deps union below) rather // than relying on its per-loader-cached module-load hook to fire during a @@ -99,7 +172,34 @@ export default class RenderMetaRoute extends Route { // visit, or an HTML render sharing this tab), the first pass finds every // target resident and `store.loaded()` resolves immediately — there is // nothing left to wait for. - await this.#settleSearchableLoads(instance, searchable); + // + // Link-load cost lives HERE: the settle passes perform the actual + // target loads (each load registers its instance in the store, so the + // timed generation below finds everything resident). The collector + // gathers one entry per performed load across all passes — a target + // loads on the first pass that reaches it and is a resident hit + // afterward — for the `searchDocLinkLoads` diagnostic. Loads the passes + // fire indirectly through field getters (a computed reading a link) + // bypass the generator's collector, so the store's completed-load + // histories are snapshotted around the loop and their delta is folded + // in — with an empty `path`, since the store can't name the owning + // field. + let recentLoadsBefore = [ + ...this.store.recentCardDocLoads(), + ...this.store.recentFileMetaLoads(), + ]; + let settleLinkLoads: SearchDocLinkLoad[] = []; + let settleStart = performance.now(); + let settlePasses = await this.#settleSearchableLoads( + instance, + searchable, + settleLinkLoads, + ); + let searchDocSettleMs = performance.now() - settleStart; + let getterFiredLoads = newLoadEntries(recentLoadsBefore, [ + ...this.store.recentCardDocLoads(), + ...this.store.recentFileMetaLoads(), + ]).map(({ url, ms }) => ({ path: '', target: url, ms })); // Union the render route's captured deps with a fresh snapshot: the // settle loop above loaded links through the tracked getter (each a @@ -193,9 +293,15 @@ export default class RenderMetaRoute extends Route { // not itself load that target. let searchDocStart = performance.now(); let searchableDeps = new Set(); + // Per-field evaluation timings come from this timed walk (link loads + // settled above, so it measures evaluation, not loading); any load the + // walk still performs — a settle that hit its pass cap, a race — joins + // the settle passes' entries. + let searchDocTimings: SearchDocTimings = { fieldsMs: {}, linkLoads: [] }; let searchDoc: Record = await searchable.searchDocFromFields( instance, searchableDeps, + searchDocTimings, ); let searchDocMs = performance.now() - searchDocStart; if (searchableDeps.size > 0) { @@ -216,6 +322,21 @@ export default class RenderMetaRoute extends Route { // `cardTitle` computed already present in the search doc. searchDoc._title = searchDoc.cardTitle; + let searchDocFieldsMs = pruneSearchDocFieldsMs( + searchDocTimings.fieldsMs ?? {}, + ); + // A target the generator loaded directly also lands in the store's + // history; keep the generator's entry (it carries the field path) and + // drop the store's duplicate. + let targetedLoads = [ + ...settleLinkLoads, + ...(searchDocTimings.linkLoads ?? []), + ]; + let targetedUrls = new Set(targetedLoads.map(({ target }) => target)); + let searchDocLinkLoads = pruneSearchDocLinkLoads([ + ...targetedLoads, + ...getterFiredLoads.filter(({ target }) => !targetedUrls.has(target)), + ]); let diagnostics: PrerenderMetaDiagnostics = { ...(passSnapshot ? { @@ -223,8 +344,12 @@ export default class RenderMetaRoute extends Route { computedCacheHits: passSnapshot.cacheHits, } : {}), - serializeMs: Math.round(serializeMs * 100) / 100, - searchDocMs: Math.round(searchDocMs * 100) / 100, + serializeMs: roundMs(serializeMs), + searchDocMs: roundMs(searchDocMs), + searchDocSettleMs: roundMs(searchDocSettleMs), + searchDocSettlePasses: settlePasses, + ...(searchDocFieldsMs ? { searchDocFieldsMs } : {}), + ...(searchDocLinkLoads ? { searchDocLinkLoads } : {}), }; // Record broken `linksTo` / `linksToMany` targets as searchable @@ -249,7 +374,7 @@ export default class RenderMetaRoute extends Route { } } computePerfLog.debug( - `render.meta computed counts cardId=${instance.id} calls=${diagnostics.computedCalls ?? 'n/a'} cacheHits=${diagnostics.computedCacheHits ?? 'n/a'} serializeMs=${diagnostics.serializeMs} searchDocMs=${diagnostics.searchDocMs}`, + `render.meta computed counts cardId=${instance.id} calls=${diagnostics.computedCalls ?? 'n/a'} cacheHits=${diagnostics.computedCacheHits ?? 'n/a'} serializeMs=${diagnostics.serializeMs} searchDocMs=${diagnostics.searchDocMs} searchDocSettleMs=${diagnostics.searchDocSettleMs} searchDocSettlePasses=${diagnostics.searchDocSettlePasses}`, ); return { @@ -273,12 +398,19 @@ export default class RenderMetaRoute extends Route { // discarded (a throwaway dependency set); the authoritative generation runs // afterward against the settled store. See the call site for why this is // needed and how it composes with the /render template settle. + // + // Returns the number of passes run. Each performed link-target load is + // recorded into `linkLoads` (the collector fills incrementally, so loads + // recorded before a swallowed mid-walk throw survive); a searchable build + // that predates the collector parameter simply leaves it empty. async #settleSearchableLoads( instance: CardDef, searchable: Awaited>, - ): Promise { + linkLoads: SearchDocLinkLoad[], + ): Promise { let observedGeneration = this.store.loadGeneration; let stablePasses = 0; + let timings: SearchDocTimings = { linkLoads }; for (let pass = 0; pass < SEARCHABLE_SETTLE_MAX_PASSES; pass++) { // A computed that reads a not-yet-loaded link (e.g. // `this.author.firstName`) throws on the first pass — the getter fires @@ -288,7 +420,7 @@ export default class RenderMetaRoute extends Route { // target. A genuine (non-load-race) failure resurfaces in the // authoritative generation the caller runs after this settles. try { - await searchable.searchDocFromFields(instance); + await searchable.searchDocFromFields(instance, undefined, timings); } catch { // intentionally ignored during settle — see above } @@ -296,7 +428,7 @@ export default class RenderMetaRoute extends Route { let nextGeneration = this.store.loadGeneration; if (nextGeneration === observedGeneration) { if (++stablePasses >= SEARCHABLE_SETTLE_REQUIRED_STABLE_PASSES) { - return; + return pass + 1; } } else { observedGeneration = nextGeneration; @@ -306,6 +438,7 @@ export default class RenderMetaRoute extends Route { computePerfLog.warn( `render.meta searchable settle for ${instance.id} did not reach a stable load generation within ${SEARCHABLE_SETTLE_MAX_PASSES} passes; proceeding with the current store state`, ); + return SEARCHABLE_SETTLE_MAX_PASSES; } } diff --git a/packages/host/tests/integration/searchable-search-doc-test.gts b/packages/host/tests/integration/searchable-search-doc-test.gts index d5f3ab8470..aecf20f973 100644 --- a/packages/host/tests/integration/searchable-search-doc-test.gts +++ b/packages/host/tests/integration/searchable-search-doc-test.gts @@ -1,7 +1,11 @@ import { getService } from '@universal-ember/test-support'; import { module, test } from 'qunit'; -import type { Realm, IndexedInstance } from '@cardstack/runtime-common'; +import type { + Realm, + IndexedInstance, + SearchDocTimings, +} from '@cardstack/runtime-common'; import type { Loader } from '@cardstack/runtime-common/loader'; import type StoreService from '@cardstack/host/services/store'; @@ -23,6 +27,7 @@ import { FieldDef, Component, StringField, + getDataBucket, searchDocFromFields, } from '../helpers/base-realm'; import { setupMockMatrix } from '../helpers/mock-matrix'; @@ -1215,4 +1220,138 @@ module('Integration | searchable search doc', function (hooks) { 'the searchable-expanded target is recorded as a dependency', ); }); + + // =========================================================================== + // the timing collector (searchDocFieldsMs / searchDocLinkLoads inputs) + // =========================================================================== + + async function loadInstance(id: string) { + let store = getService('store') as StoreService; + return (await store.get(id)) as CardDefType; + } + + // A store-resident instance can arrive with its link fields already + // materialized, in which case the generator has no load to perform (and + // correctly records none). Reset a link slot to its unloaded wire state so + // the walk drives the load itself — the state an indexing visit starts + // from. + function unloadLink( + instance: CardDefType, + fieldName: string, + reference: string | string[], + ) { + getDataBucket(instance).set( + fieldName, + Array.isArray(reference) + ? reference.map((r) => ({ type: 'not-loaded', reference: r })) + : { type: 'not-loaded', reference }, + ); + } + + test('per-field timings are keyed by dotted path and include expanded link targets; link loads carry path + target', async function (assert) { + let instance = await loadInstance(`${testRealmURL}ArticleDeep/d1`); + let author = await loadInstance(authorUrl); + unloadLink(instance, 'author', authorUrl); + unloadLink(author, 'agent', agentUrl); + let timings: SearchDocTimings = { fieldsMs: {}, linkLoads: [] }; + let doc = await searchDocFromFields(instance, undefined, timings); + + let fieldsMs = timings.fieldsMs!; + for (let path of ['title', 'author', 'author.agent']) { + assert.strictEqual( + typeof fieldsMs[path], + 'number', + `fieldsMs['${path}'] is a number, got: ${fieldsMs[path]}`, + ); + assert.ok( + fieldsMs[path] >= 0, + `fieldsMs['${path}'] is non-negative, got: ${fieldsMs[path]}`, + ); + } + assert.ok( + fieldsMs['author'] >= fieldsMs['author.agent'], + 'a parent field time is inclusive of its nested fields', + ); + + let loads = timings.linkLoads!; + assert.ok( + loads.some((l) => l.path === 'author' && l.target === authorUrl), + `the author load is recorded with its path and target, got: ${JSON.stringify(loads)}`, + ); + assert.ok( + loads.some((l) => l.path === 'author.agent' && l.target === agentUrl), + 'the route-expanded deeper load is recorded under its dotted path', + ); + assert.ok( + loads.every((l) => typeof l.ms === 'number' && l.ms >= 0), + 'every load entry carries a non-negative ms', + ); + + // Instrumentation must not perturb the doc itself. + assert.deepEqual( + doc, + await searchDocFromFields(instance), + 'the instrumented walk produces the same doc as an uninstrumented one', + ); + }); + + test('a plural field accumulates under one path key and records one load per slot', async function (assert) { + let instance = await loadInstance(`${testRealmURL}Team/valid`); + unloadLink(instance, 'members', [ + `${testRealmURL}Author/au1`, + `${testRealmURL}Author/au2`, + ]); + let timings: SearchDocTimings = { fieldsMs: {}, linkLoads: [] }; + await searchDocFromFields(instance, undefined, timings); + + let memberKeys = Object.keys(timings.fieldsMs!).filter( + (k) => k === 'members' || k.startsWith('members.'), + ); + assert.ok( + memberKeys.includes('members'), + 'the plural field has a single accumulated key', + ); + assert.ok( + memberKeys.includes('members.name'), + "the expanded members' fields accumulate under the shared dotted path", + ); + + let memberLoads = timings.linkLoads!.filter((l) => l.path === 'members'); + assert.deepEqual( + memberLoads.map((l) => l.target).sort(), + [`${testRealmURL}Author/au1`, `${testRealmURL}Author/au2`], + 'each slot records its own load, distinguished by target', + ); + }); + + test('collector channels are opt-in', async function (assert) { + let instance = await loadInstance(`${testRealmURL}ArticleSelf/s1`); + unloadLink(instance, 'author', authorUrl); + + let fieldsOnly: SearchDocTimings = { fieldsMs: {} }; + await searchDocFromFields(instance, undefined, fieldsOnly); + assert.ok( + Object.keys(fieldsOnly.fieldsMs!).length > 0, + 'the supplied fields channel is filled', + ); + assert.strictEqual( + fieldsOnly.linkLoads, + undefined, + 'the absent loads channel is not created', + ); + + let loadsOnly: SearchDocTimings = { linkLoads: [] }; + await searchDocFromFields(instance, undefined, loadsOnly); + assert.ok( + loadsOnly.linkLoads!.some( + (l) => l.path === 'author' && l.target === authorUrl, + ), + 'the supplied loads channel is filled', + ); + assert.strictEqual( + loadsOnly.fieldsMs, + undefined, + 'the absent fields channel is not created', + ); + }); }); diff --git a/packages/host/tests/unit/search-doc-load-diff-test.ts b/packages/host/tests/unit/search-doc-load-diff-test.ts new file mode 100644 index 0000000000..ac1cab5a66 --- /dev/null +++ b/packages/host/tests/unit/search-doc-load-diff-test.ts @@ -0,0 +1,33 @@ +import { module, test } from 'qunit'; + +import { newLoadEntries } from '@cardstack/host/routes/render/meta'; + +// The store's completed-load histories are bounded top-N lists that persist +// across renders on a warm tab; `newLoadEntries` extracts just the loads a +// settle loop performed by multiset-diffing snapshots taken around it. +module('Unit | render meta | newLoadEntries', function () { + const A = { url: 'https://realm.example/a', ms: 12 }; + const B = { url: 'https://realm.example/b', ms: 340 }; + const C = { url: 'https://realm.example/c', ms: 5 }; + + test('returns entries present only in the after snapshot', function (assert) { + assert.deepEqual(newLoadEntries([A], [A, B]), [B]); + }); + + test('returns everything when the before snapshot is empty', function (assert) { + assert.deepEqual(newLoadEntries([], [A, B]), [A, B]); + }); + + test('multiset semantics: a repeated (url, ms) pair only reports the excess occurrences', function (assert) { + assert.deepEqual(newLoadEntries([A, A], [A, A, A, B]), [A, B]); + }); + + test('an entry evicted from the bounded history produces nothing', function (assert) { + assert.deepEqual(newLoadEntries([A, C], [A, B]), [B]); + }); + + test('same url with a different ms is a distinct load', function (assert) { + let rerun = { url: A.url, ms: 99 }; + assert.deepEqual(newLoadEntries([A], [A, rerun]), [rerun]); + }); +}); diff --git a/packages/realm-server/tests/indexing-test.ts b/packages/realm-server/tests/indexing-test.ts index a25f8f857f..b415487929 100644 --- a/packages/realm-server/tests/indexing-test.ts +++ b/packages/realm-server/tests/indexing-test.ts @@ -791,6 +791,23 @@ module(basename(import.meta.filename), function () { ['error', 'not-found'].includes(brokenLinks?.[0]?.kind ?? ''), `broken-link finding carries a terminal kind, got: ${brokenLinks?.[0]?.kind}`, ); + + // The search-doc settle aggregates ride the same channel onto the + // persisted row: render.meta stamps them on every card visit. + let diagnostics = diagRow?.diagnostics as + | { searchDocSettleMs?: unknown; searchDocSettlePasses?: unknown } + | null + | undefined; + assert.strictEqual( + typeof diagnostics?.searchDocSettleMs, + 'number', + `diagnostics.searchDocSettleMs persists on boxel_index, got: ${JSON.stringify(diagnostics?.searchDocSettleMs)}`, + ); + assert.strictEqual( + typeof diagnostics?.searchDocSettlePasses, + 'number', + `diagnostics.searchDocSettlePasses persists on boxel_index, got: ${JSON.stringify(diagnostics?.searchDocSettlePasses)}`, + ); }); // Note this particular test should only be a server test as the nature of diff --git a/packages/realm-server/tests/prerendering-test.ts b/packages/realm-server/tests/prerendering-test.ts index bd20cda06d..1cefff8073 100644 --- a/packages/realm-server/tests/prerendering-test.ts +++ b/packages/realm-server/tests/prerendering-test.ts @@ -1531,6 +1531,61 @@ module(basename(import.meta.filename), function () { ); }); + test('card prerender records the search-doc settle aggregates on meta.diagnostics for persistence', async function (assert) { + // The settle aggregates ride the same consolidated diagnostics + // channel as the timings and broken-link findings: render.meta + // stamps searchDocSettleMs / searchDocSettlePasses on every card + // visit, and the Prerenderer lifts them onto + // `response.meta.diagnostics` — the blob the indexer flattens into + // `boxel_index.diagnostics`. The per-field / per-link-load detail + // (searchDocFieldsMs / searchDocLinkLoads) is floor-bounded so its + // presence depends on real timings; only its shape is asserted when + // it appears. + let result = await prerenderer.prerenderVisit({ + affinityType: 'realm', + affinityValue: realmURL, + realm: realmURL, + url: `${realmURL}1.json`, + auth: auth(), + renderOptions: { cardRender: true }, + }); + + assert.notOk(result.response.card?.error, 'prerender succeeds'); + let diagnostics = result.response.meta?.diagnostics; + assert.strictEqual( + typeof diagnostics?.searchDocSettleMs, + 'number', + `searchDocSettleMs is stamped, got: ${diagnostics?.searchDocSettleMs}`, + ); + assert.ok( + (diagnostics?.searchDocSettleMs ?? -1) >= 0, + `searchDocSettleMs is non-negative, got: ${diagnostics?.searchDocSettleMs}`, + ); + assert.ok( + (diagnostics?.searchDocSettlePasses ?? 0) >= 2, + `searchDocSettlePasses counts at least the two stability passes, got: ${diagnostics?.searchDocSettlePasses}`, + ); + if (diagnostics?.searchDocFieldsMs !== undefined) { + assert.ok( + Object.values(diagnostics.searchDocFieldsMs).every( + (ms) => typeof ms === 'number' && ms >= 1, + ), + 'retained per-field timings are all at/over the persistence floor', + ); + } + if (diagnostics?.searchDocLinkLoads !== undefined) { + assert.ok( + diagnostics.searchDocLinkLoads.every( + (l) => + typeof l.path === 'string' && + typeof l.target === 'string' && + l.ms >= 1, + ), + 'retained link loads carry path + target and are at/over the floor', + ); + } + }); + test('card prerender surfaces actionable error for bad icon import', async function (assert) { let cardURL = `${realmURL}bad-icon-import.json`; diff --git a/packages/runtime-common/index.ts b/packages/runtime-common/index.ts index 3e0314e207..e85adebf4c 100644 --- a/packages/runtime-common/index.ts +++ b/packages/runtime-common/index.ts @@ -103,6 +103,39 @@ export const FRONTMATTER_PARSE_ERROR_SYMBOL = Symbol.for( 'boxel:file-frontmatter-parse-error', ); +// One performed load of a link target during search-doc production. `path` +// is the dotted field path (from the indexed card's root) of the `linksTo` / +// `linksToMany` field that owns the link; `target` is the resolved +// (absolute) URL that was loaded. A `linksToMany` field produces one entry +// per loaded slot, all sharing the field's `path` and distinguished by +// `target`. A load fired through a field getter — a computed reading a link +// loads via the getter's lazy path, not the generator's targeted loading — +// carries an empty `path`, since the store observing it can't name the +// owning field. Only actual loads are represented — a target already +// resident in the store records a near-zero entry that the persistence +// floor drops. +export interface SearchDocLinkLoad { + path: string; + target: string; + ms: number; +} + +// Mutable out-param collector `searchDocFromFields` fills in place while it +// walks the card. Each sub-collector is opt-in: the generator only spends +// timer calls on the channels the caller supplies. Values are raw +// (unbounded, unrounded) — the render.meta route prunes to the slowest +// entries before persisting onto `boxel_index.diagnostics`. +export interface SearchDocTimings { + // Dotted field path → inclusive evaluation wall-clock. A parent field's + // time includes its nested fields' (and its link loads'), so a slow leaf + // surfaces alongside every ancestor on its path — the drill-down reads + // directly from the keys. Plural fields accumulate across their items + // under one key. + fieldsMs?: Record; + // One entry per link-target load the walk performed. + linkLoads?: SearchDocLinkLoad[]; +} + // Per-render computed-field counters captured by the host's render.meta // route. Emitted alongside PrerenderMeta so the Prerenderer can lift them // onto `response.meta.diagnostics` and the indexer can persist them onto @@ -123,6 +156,34 @@ export interface PrerenderMetaDiagnostics { serializeMs?: number; // Wall-clock of the host-side searchDoc call. searchDocMs?: number; + // Wall-clock of the searchable load-settle loop that runs before the + // timed searchDoc call: the passes that drive the card's searchable-path + // link loads (and the links its contained/computed fields read) to + // quiescence. Link-load cost lives HERE, not inside `searchDocMs` — by + // the time the timed generation runs, its targets are resident. Read + // `searchDocLinkLoads` for the per-target breakdown of this time. + searchDocSettleMs?: number; + // How many settle passes ran before the store's load generation held + // steady. Each pass loads one more dependency-depth wave, so a high count + // means a deep searchable/computed link chain (capped host-side; the cap + // logs a warning). + searchDocSettlePasses?: number; + // Per-field inclusive evaluation timings from the timed searchDoc walk, + // keyed by dotted field path from the indexed card's root (a parent's + // time includes its children's, so a slow leaf appears alongside its + // ancestors). Bounded: only the slowest fields at/over a floor are + // persisted, so a typical ~1 ms search doc records nothing and a slow one + // records its hot paths — the retained entries' (top-level) sum accounts + // for `searchDocMs`. A large `searchDocMs` with NO entries means death by + // a thousand cheap fields rather than one hot path. Omitted when empty. + searchDocFieldsMs?: Record; + // The slowest searchable link-target loads performed while producing this + // row's search doc — the settle passes' loads plus any the timed walk + // still performed — same bounding as `searchDocFieldsMs`. Separates "the + // linked instance was slow to load" (an entry here) from "the field was + // expensive to compute" (a hot `searchDocFieldsMs` path with no matching + // load). Omitted when empty. + searchDocLinkLoads?: SearchDocLinkLoad[]; // Broken `linksTo` / `linksToMany` targets found on the rendered // instance after the store settled. Captured by the render.meta scan // and persisted to `boxel_index.diagnostics.brokenLinks` so