diff --git a/.claude/skills/indexing-diagnostics/SKILL.md b/.claude/skills/indexing-diagnostics/SKILL.md index 708c2829c8e..3df5913b58d 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, 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`, and (8) decomposing the between-visit / non-render slice of an index job's wall — the once-per-job phases (invalidation discovery, dependency ordering, module pre-warm, aggregate row writes, the final swap) on `jobs.result.phaseTimings` plus the per-row client overhead (file read / render round-trip transport / post-render bookkeeping) on `boxel_index.diagnostics.indexVisitClientMs` — the wall that runs serially between the server renders and is invisible in the per-row `totalElapsedMs`, and (9) decomposing a trivial card's fixed per-visit floor — the route machinery (the meta / icon / file-extract route transitions, instantiation, and per-visit request plumbing) around the search-doc work — into per-route wall-clock buckets on `boxel_index.diagnostics.indexRoutesMs` (the index-half sibling of the render channel's `renderFormatsMs`), so a floor that isn't the search doc reads as measured route steps rather than an inference from `renderElapsedMs`, and (10) recognizing a batch-level setup-phase failure of an incremental job — N error docs sharing one `error_doc.message` and `job_id`, carrying no visit diagnostics, from a rejected job whose whole batch failed before its visit loop — vs per-row render failures, and the re-push recovery those error docs enable, and (11) explaining a missing declared screenshot / thumbnail via `prerendered_html.diagnostics.screenshotErrors` (the row publishes normally — this is the only indexed signal, with per-slot `consecutiveFailures` reporting and the row-level `screenshotCaptureFailureRenders` counter the reconcile sweep's retry cap is enforced against) and attributing slow captures per slot via `screenshotTimingsMs`, the per-name decomposition of `renderFormatsMs.card.screenshots`. 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, when a trivial-search-doc card still costs far more per visit than its doc justifies and you need to attribute the per-visit floor to a route step, 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`, and (8) decomposing the between-visit / non-render slice of an index job's wall — the once-per-job phases (invalidation discovery, dependency ordering, module pre-warm, aggregate row writes, the final swap) on `jobs.result.phaseTimings` plus the per-row client overhead (file read / render round-trip transport / post-render bookkeeping) on `boxel_index.diagnostics.indexVisitClientMs` — the wall that runs serially between the server renders and is invisible in the per-row `totalElapsedMs`, and (9) decomposing a trivial card's fixed per-visit floor — the route machinery (the meta / icon / file-extract route transitions, instantiation, and per-visit request plumbing) around the search-doc work — into per-route wall-clock buckets on `boxel_index.diagnostics.indexRoutesMs` (the index-half sibling of the render channel's `renderFormatsMs`), so a floor that isn't the search doc reads as measured route steps rather than an inference from `renderElapsedMs`, and (10) recognizing a batch-level setup-phase failure of an incremental job — N error docs sharing one `error_doc.message` and `job_id`, carrying no visit diagnostics, from a rejected job whose whole batch failed before its visit loop — vs per-row render failures, and the re-push recovery those error docs enable, and (11) explaining a missing declared screenshot / thumbnail via `prerendered_html.diagnostics.screenshotErrors` (the row publishes normally — this is the only indexed signal, with per-slot `consecutiveFailures` reporting and the row-level `screenshotCaptureFailureRenders` counter the reconcile sweep's retry cap is enforced against) and attributing slow captures per slot via `screenshotTimingsMs`, the per-name decomposition of `renderFormatsMs.card.screenshots`, and (12) reconstructing the order a pass wrote its rows in — `diagnostics.writeSeq` (a per-batch 0-based write counter on both channels; `indexedAt` is millisecond-resolution and a buffered multi-row upsert stamps a whole flush identically, so it cannot order rows within a pass), which separates the URLs a write actually named from the dependents its fan-out discovered (an incremental index pass writes its targets first) and says how far into its plan a stalled job got. 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, when a trivial-search-doc card still costs far more per visit than its doc justifies and you need to attribute the per-visit floor to a route step, when you need to know what order a pass indexed its rows in or which of them the triggering write actually named, 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 --- @@ -23,9 +23,9 @@ The first three read from the same `diagnostics` column; the difference is the q Seven 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`, `searchDocSettleMs`/`searchDocSettlePasses`, `searchDocFieldsMs`, `searchDocLinkLoads`, `computedCalls`/`computedCacheHits`), the per-route `indexRoutesMs` breakdown (the index-half sibling of the render channel's `renderFormatsMs` — the wall-clock of each index-visit route step, so the per-visit floor decomposes into `meta` / `icon` / `fileExtract` buckets; see [Mode L](#mode-l--the-index-visits-per-route-floor-meta--icon--file-extract)), and three write-side stamps: `invalidationId`, `indexedAt`, `requestId`. It also carries an `indexVisitClientMs` block (`read` / `renderRpc` / `bookkeeping`) — the indexer's per-row client-side overhead _outside_ the server render, i.e. this row's slice of the between-visit wall (see [Mode K](#mode-k--the-index-jobs-between-visit-wall-non-render-overhead)) — and 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 `brokenLinks` 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 it's 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). On instance rows it also carries the declared-screenshot channel: `screenshotTimingsMs` (per-slot capture wall-clock) and `screenshotErrors` (per-slot capture failures with their `consecutiveFailures` retry bookkeeping) — see [Mode M](#mode-m--declared-screenshot-capture-failures-and-per-slot-timings). 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. +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`), the per-route `indexRoutesMs` breakdown (the index-half sibling of the render channel's `renderFormatsMs` — the wall-clock of each index-visit route step, so the per-visit floor decomposes into `meta` / `icon` / `fileExtract` buckets; see [Mode L](#mode-l--the-index-visits-per-route-floor-meta--icon--file-extract)), and the write-side stamps: `invalidationId`, `indexedAt`, `writeSeq` (this row's position in its pass's write order — the only field that orders two rows of the same pass; see [Reconstructing a pass's write order](#reconstructing-a-passs-write-order)), and `requestId`. It also carries an `indexVisitClientMs` block (`read` / `renderRpc` / `bookkeeping`) — the indexer's per-row client-side overhead _outside_ the server render, i.e. this row's slice of the between-visit wall (see [Mode K](#mode-k--the-index-jobs-between-visit-wall-non-render-overhead)) — and 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 `brokenLinks` 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 it's 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). On instance rows it also carries the declared-screenshot channel: `screenshotTimingsMs` (per-slot capture wall-clock) and `screenshotErrors` (per-slot capture failures with their `consecutiveFailures` retry bookkeeping) — see [Mode M](#mode-m--declared-screenshot-capture-failures-and-per-slot-timings). It carries the same three write-side stamps as the index channel — `invalidationId`, `indexedAt`, `writeSeq` — on **every** live row, whether or not the render reported timings of its own, so a `prerender_html` job's fan-out groups and orders exactly like an index pass's. **The two channels' `invalidationId`s are different**: the id is scoped to a `Batch`, and an index pass and the `prerender_html` job it spawns are separate batches. Each id groups its own channel; join the channels on `url` (plus `generation`), never on `invalidationId`. 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; none of the write-side stamps — no `invalidationId` and no `writeSeq` (module rows aren't written by a `Batch` at all). 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. 5. **Logs** — `prerender-server`, `manager`, and `remote-prerenderer` lines all carry `requestId=…`. `grep requestId=` collates one call across all three processes. The same id lands on `boxel_index.diagnostics->>'requestId'` and `modules.diagnostics->>'requestId'` — and, for the render channel, on `prerendered_html.diagnostics->>'prerenderHtmlRequestId'` — so a hung card render and the module renders it triggered (via `getDefinition`) can be joined back to one investigation. For saturation incidents there's also the periodic `prerender-queue-snapshot` line on each prerender server. 6. **Realm-server search-timing logs** — separate from the prerender `requestId` chain above. The realm-server emits, per instrumented `_federated-search`, a `realm:search-timing` line (request→response stage breakdown) and a `realm:requests` `-->` line with `dur=` (total) — both keyed by `corr=`, the `x-boxel-logging-correlation-id` the prerendered host stamps. A periodic `realm:health` line reports event-loop lag + in-flight `_search` count during saturation windows. These are the _server's_ view of the search the card is blocked on; the card's `boxel_index.diagnostics` only has the _client's_ view (`queryLoadsInFlight`). See [Mode G](#mode-g--an-in-render-_search-was-slow-server-side-search-timing). @@ -46,14 +46,16 @@ 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 per-route floor split (`indexRoutesMs` — one number per index-visit route step, split into a `card` block `meta` / `icon` and a `file` block `fileExtract` / `icon`; see [Mode L](#mode-l--the-index-visits-per-route-floor-meta--icon--file-extract)), the search-doc build (`serializeMs`, `searchDocMs`, `searchDocSettleMs`/`searchDocSettlePasses`, the per-field `searchDocFieldsMs` and per-link-load `searchDocLinkLoads` detail, `computedCalls`/`computedCacheHits`), the indexer's own per-row client overhead outside the render (`indexVisitClientMs`: `read` / `renderRpc` / `bookkeeping` — see [Mode K](#mode-k--the-index-jobs-between-visit-wall-non-render-overhead)), `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; `card.screenshots` is the declared-screenshot capture step's aggregate, decomposed per slot by `screenshotTimingsMs`). Instance rows also carry `screenshotErrors` — per-slot declared-capture failures, the only indexed signal a declared screenshot is missing (see [Mode M](#mode-m--declared-screenshot-capture-failures-and-per-slot-timings)). HTTP id: `prerenderHtmlRequestId`. | +| where | visit | what's in it | +| ------------------------------ | -------------------- | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | +| `boxel_index.diagnostics` | index visit | that visit's server timings (`launchMs`, `waits`, `renderElapsedMs`, `totalElapsedMs`), the per-route floor split (`indexRoutesMs` — one number per index-visit route step, split into a `card` block `meta` / `icon` and a `file` block `fileExtract` / `icon`; see [Mode L](#mode-l--the-index-visits-per-route-floor-meta--icon--file-extract)), the search-doc build (`serializeMs`, `searchDocMs`, `searchDocSettleMs`/`searchDocSettlePasses`, the per-field `searchDocFieldsMs` and per-link-load `searchDocLinkLoads` detail, `computedCalls`/`computedCacheHits`), the indexer's own per-row client overhead outside the render (`indexVisitClientMs`: `read` / `renderRpc` / `bookkeeping` — see [Mode K](#mode-k--the-index-jobs-between-visit-wall-non-render-overhead)), `brokenLinks`, and the write-side stamps (`invalidationId`, `indexedAt`, `writeSeq`). 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; `card.screenshots` is the declared-screenshot capture step's aggregate, decomposed per slot by `screenshotTimingsMs`). Instance rows also carry `screenshotErrors` — per-slot declared-capture failures, the only indexed signal a declared screenshot is missing (see [Mode M](#mode-m--declared-screenshot-capture-failures-and-per-slot-timings)). Same write-side stamps as the index channel (`invalidationId`, `indexedAt`, `writeSeq`), scoped to the `prerender_html` job's own batch. 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`. Each side names the sub-step that dominated its channel: on the index side `indexRoutesMs` names the route (a slow `meta` build vs an `icon` render vs `fileExtract`), on the render side `renderFormatsMs` names the format (a slow `isolated` template vs a `fitted` render fanning out across many ancestors). -The field-name → visit mapping is constant across both tables: `requestId` always names an index visit's HTTP request, `prerenderHtmlRequestId` always names a prerender-html visit's. Join a row's two halves on url (each table keys on `(url, realm_url, type)`), then carry each side's id into the log search: +The field-name → visit mapping is constant across both tables: `requestId` always names an index visit's HTTP request, `prerenderHtmlRequestId` always names a prerender-html visit's. The write-side stamps follow the same rule — they describe the batch that wrote **that** row, so `invalidationId` and `writeSeq` are only comparable within one table's fan-out. A split pipeline's two channels are two batches, and each numbers its own writes from 0; a fused pass (the SQLite in-browser path) is one batch, and a visit's two halves share one `writeSeq` because they are one position, not two. + +Join a row's two halves on url (each table keys on `(url, realm_url, type)`), then carry each side's id into the log search: ```sql SELECT b.url, @@ -133,7 +135,9 @@ Walk the fields per [Classify in one pass](#classify-in-one-pass). The _first_ p ## Mode B — an incremental reindex was slow -Every `Batch.invalidate(urls)` call mints a UUID stashed into `diagnostics.invalidationId` for every row written during that fan-out. If a `.gts` edit invalidates 8 rows (one file + seven card instances), all eight carry the same `invalidationId` — so you can look at the whole reindex as a group. +Every `Batch.invalidate(urls)` call mints a UUID stashed into `diagnostics.invalidationId` for every row written during that fan-out. If a `.gts` edit invalidates 8 rows (one file + seven card instances), all eight carry the same `invalidationId` — so you can look at the whole reindex as a group. `diagnostics.writeSeq` then orders that group; see [Reconstructing a pass's write order](#reconstructing-a-passs-write-order) below. + +The same pair works on the render channel, where the `prerender_html` job's own batch id groups its renderings and its own `writeSeq` orders them. The two ids differ — see [Where the diagnostics live](#where-the-diagnostics-live) item 2. **Step 1 — find the invalidation you care about.** If you don't already have the ID, discover recent big ones: @@ -182,11 +186,40 @@ WHERE realm_url = 'https://localhost:4201/user/your-realm/' ORDER BY render_ms DESC NULLS LAST; ``` +### Reconstructing a pass's write order + +`writeSeq` is the pass's own write order — a 0-based counter advanced as each row enters the writer, so it survives the write-behind buffer that gives a whole flush of rows one identical `indexedAt`. **`indexedAt` cannot order rows within a pass** (it resolves to the millisecond and a buffered multi-row upsert stamps them all the same); `writeSeq` is the only field that can. Order by it, not by `indexedAt`: + +```sql +SELECT + (diagnostics->>'writeSeq')::int AS seq, + url, + type, + has_error, + (diagnostics->>'renderElapsedMs')::int AS render_ms +FROM boxel_index +WHERE realm_url = 'https://localhost:4201/user/your-realm/' + AND diagnostics->>'invalidationId' = '' +ORDER BY seq; +``` + +Two things this tells you: + +- **Which URLs the write actually named.** An incremental pass writes its **targets** — the URLs the triggering write named — before the dependents its fan-out discovered, so the lowest sequences in a fan-out are the targets and everything after them is dep closure. This is a guarantee, not a coincidence: `prioritizeWrittenURLs` in `index-runner.ts` ranks the written URLs ahead of the discovered ones and the topological ordering treats that rank as a priority. Exactly two things outrank being a target: + - **Visit class.** `realm.json` first, then non-`.json` files, then `.json` files — so every module in the fan-out is written before every instance, target or not. An instance whose module has no file entry yet cannot render at all, which is why this is not negotiable. + - **A recorded dependency.** A URL whose `deps` row names another URL in the same set is written after it. The exception is a dependency **cycle**: no order satisfies one, so the edges inside it are dropped and its members compete on priority like everything else — a target stranded in a cycle still leads. + + So a target appearing after a _module_, or after a URL it declares a dependency on, is expected; a target appearing after an unrelated _instance_ is not, and is worth a second look. + +- **Where a stalled pass got to.** See [step 6](#6-reading-partial-progress-from-boxel_index_working). + +A card instance contributes two rows buffered back to back — its `file` row and its `instance` row — so reduce to one position per URL with `min((diagnostics->>'writeSeq')::int) … GROUP BY url` when you want a per-URL order. (A module has only a `file` row, so the reduction is a no-op for it.) A row written twice in one pass keeps the position of its first write and its second consumes none, so a pass's sequences are gapless — a missing position means a row you are not looking at, not a rewrite. + **Step 3 — classify each slow row.** For the top offenders, pull the full `diagnostics` and apply the [Classify in one pass](#classify-in-one-pass) table to each. Common patterns: - One row dominates (e.g. a dashboard card) and the rest are cheap. The big row is the real target — investigate its `queryLoadsInFlight` / `recentModuleEvaluations` / `cardDocLoadsInFlight`. - All rows share a large `launchMs`. Capacity contention during the reindex, not the cards' fault. -- The first row in the batch (min `indexedAt`) has a large `renderElapsedMs` but the rest are cheap — this is the cold-loader tax paid by whichever card was rendered first after `clearCache: true` fired. Expected on any executable invalidation; only worth chasing if the cold cost is disproportionate to the dep closure. +- The first row written (`writeSeq = 0`) has a large `renderElapsedMs` but the rest are cheap — this is the cold-loader tax paid by whichever card was rendered first after `clearCache: true` fired. Expected on any executable invalidation; only worth chasing if the cold cost is disproportionate to the dep closure. - The `deps` / `types` columns on the same rows tell you _why_ each row was invalidated — useful for discovering unintentionally-heavy transitive deps (e.g. a dashboard re-renders because one of its metrics modules has a runtime reference to the changed module). **Other useful queries:** @@ -257,7 +290,7 @@ Recovery for the errored URLs is any later write touching them (error rows are e For everything else in this mode the diagnostic stance flips from "what timed out" (Mode A) or "what was slow" (Mode B) to **"what hasn't happened yet"**. You're reconstructing the work the job _would have done_ from three sources together: -1. **`boxel_index_working`** — the staging table the indexer writes to as it makes progress. On success its rows for the touched URLs are copied into `boxel_index` (`Batch.applyBatchUpdates` in `packages/runtime-common/index-writer.ts`). On failure (worker crash, job timeout, manual cancel) the working rows are left behind, which is exactly the bisection signal you want: any row in `boxel_index_working` that is _not yet_ in `boxel_index` (or has a higher `realm_version`) was already processed by the stuck job. +1. **`boxel_index_working`** — the staging table the indexer writes to as it makes progress. On success its rows for the touched URLs are copied into `boxel_index` (`Batch.applyBatchUpdates` in `packages/runtime-common/index-writer.ts`). On failure (worker crash, job timeout, manual cancel) the working rows are left behind, which is exactly the bisection signal you want: any row in `boxel_index_working` that is _not yet_ in `boxel_index` (or has a higher `generation`) was already processed by the stuck job. 2. **EFS file mtimes** — reachable via the `aws-access` skill's "Browsing the EFS filesystem" path (the `boxel-claude-fs-readonly-` Fargate task). Combined with `boxel_index.last_modified` (the indexer's view of when each file was last processed) this lets you reconstruct what _would_ have been invalidated by a from-scratch run, _before_ any `boxel_index_working` rows existed. 3. **Worker logs** in CloudWatch (`ecs-boxel-worker-`) — confirms the job's start, the file it was on at the freeze point, and any partial completion lines. @@ -441,7 +474,7 @@ The fan-out is **iterative**, not a single recursive CTE. `Batch.invalidate(urls - For executable file rows (`.gts` / `.ts` / `.js` / `.gjs`) with a `file_alias`: the `file_alias` (path with extension trimmed). Executable consumers see the _aliased_ URL in `deps`, not the source file with extension. - Otherwise (non-executable file rows): the row's `url`. -5. After the loop converges (no new URLs added to `visited`), `tombstoneEntries(invalidations)` (line 684) inserts a `is_deleted = true` row for every invalidated URL into `boxel_index_working` with `realm_version = `, stamped with the batch's current `invalidationId`. **This is the first DB-side write of the batch.** If the worker died before this, `boxel_index_working` will not yet contain partial-progress rows for the new realm version (step 6 will be empty). +5. After the loop converges (no new URLs added to `visited`), `tombstoneEntries(invalidations)` (line 684) inserts a `is_deleted = true` row for every invalidated URL into `boxel_index_working` with `generation = `, stamped with the batch's current `invalidationId`. **This is the first DB-side write of the batch.** If the worker died before this, `boxel_index_working` will not yet contain partial-progress rows for the new realm version (step 6 will be empty). To reconstruct the consumer set against the live DB, run the iteration manually: @@ -476,22 +509,28 @@ Two-hop fan-out: rerun with the first hop's `(url, file_alias, type)` plugged in ### 6. Reading partial progress from `boxel_index_working` -`boxel_index_working` carries the batch's in-progress writes, keyed by `(url, realm_url)`. The indexer writes here continuously via `Batch.updateEntry` (line 310). On `Batch.done()` (line 476), rows are copied into `boxel_index` with the new `realm_version` and the working table is **left in place** — it's not truncated (each invalidation is keyed by realm version inside the table). For a stuck job, the rows already written carry the same `invalidationId` and bracket the freeze point. +`boxel_index_working` carries the batch's in-progress writes, keyed by `(url, realm_url)`. The indexer writes here continuously via `Batch.updateEntry` (line 310). On `Batch.done()` (line 476), rows are copied into `boxel_index` with the new `generation` and the working table is **left in place** — it's not truncated (each invalidation is keyed by realm version inside the table). For a stuck job, the rows already written carry the same `invalidationId` and bracket the freeze point. ```sql -- Partial progress for a stuck batch: rows the in-progress job has --- already written, ordered by indexedAt so the bottom row is the file +-- already written, ordered by writeSeq so the bottom row is the file -- that was being worked on when things froze. -- +-- Order by writeSeq, NOT indexedAt: rows drain through a write-behind +-- buffer that stamps a whole flush with one identical millisecond, so +-- indexedAt cannot separate them and an indexedAt sort silently returns +-- an arbitrary order within each flush. +-- -- The diagnostic projection mirrors Mode B's fan-out query — use -- diagnostics->>'renderStage' / 'currentlyEvaluatingModule' / -- 'recentModuleEvaluations[0].url' to identify the specific module the -- worker stalled on. SELECT + (diagnostics->>'writeSeq')::int AS seq, url, type, has_error, - realm_version, + generation, to_timestamp((diagnostics->>'indexedAt')::bigint / 1000) AS indexed_at, diagnostics->>'invalidationId' AS invalidation_id, @@ -508,7 +547,7 @@ SELECT FROM boxel_index_working WHERE realm_url = '' AND diagnostics->>'invalidationId' = '' -ORDER BY (diagnostics->>'indexedAt')::bigint ASC; +ORDER BY seq ASC; ``` If you don't already have an `invalidationId`, find the most recent batch's ID against the working table (the last `updateEntry` for the realm wins): @@ -516,14 +555,15 @@ If you don't already have an `invalidationId`, find the most recent batch's ID a ```sql SELECT diagnostics->>'invalidationId' AS invalidation_id, - realm_version, + generation, count(*) AS rows_written, to_timestamp( min((diagnostics->>'indexedAt')::bigint) / 1000 ) AS first_write, to_timestamp( max((diagnostics->>'indexedAt')::bigint) / 1000 - ) AS last_write + ) AS last_write, + max((diagnostics->>'writeSeq')::int) AS rows_deep FROM boxel_index_working WHERE realm_url = '' AND diagnostics->>'invalidationId' IS NOT NULL @@ -532,9 +572,28 @@ ORDER BY last_write DESC LIMIT 10; ``` -The bottom row of the per-`invalidationId` query (max `indexedAt`) is **the most recently completed file**; the file the worker stalled on is most likely the _next_ one in the planned visit order (which is sorted in `index-runner.ts::sortInvalidations` — `.json` files visited after their non-`.json` counterparts; otherwise lexical by href). Combine three signals to pin it down: +`rows_deep` is how far into its write order the batch got. A URL contributes two rows, so it is roughly twice the number of files visited; for the planned total and a files-completed count, read the job's `job_progress` row (`total_files` / `files_completed` — an UNLOGGED table the manager's `IndexingEventSink` upserts from the worker's progress events, debounced, so it can lag the last write by a tick). + +**A retried job holds two batches' worth of rows.** When an expired reservation is retried, `loadResumedRows` keeps the previous attempt's working rows exactly as they are and promotes them alongside the new attempt's — so the promoted generation mixes two `invalidationId`s, each numbered from 0. Grouping by the newest id shows only what this attempt re-visited and silently omits every URL the earlier attempt already finished, which for a stuck-job investigation is precisely the wrong half. Find every id at the generation first, then union them: -1. The bottom row's `url` is the last-completed file. +```sql +SELECT diagnostics->>'invalidationId' AS invalidation_id, + count(*) AS rows_written, + min((diagnostics->>'writeSeq')::int) AS first_seq, + max((diagnostics->>'writeSeq')::int) AS last_seq +FROM boxel_index_working +WHERE realm_url = '' + AND job_id = + AND diagnostics->>'writeSeq' IS NOT NULL +GROUP BY 1 +ORDER BY min((diagnostics->>'indexedAt')::bigint); +``` + +Sequences are only comparable within one id, so order each attempt's rows separately — `indexedAt` is what puts the attempts in order relative to each other. + +The bottom row of the per-`invalidationId` query (max `writeSeq`) is **the most recently completed file**; the file the worker stalled on is most likely the _next_ one in the planned visit order. That order is: `index-runner.ts::sortInvalidations` (realm config first, then non-`.json` files before the `.json` ones that depend on them, otherwise lexical by href), then `prioritizeWrittenURLs` hoists the URLs the triggering write named ahead of the dependents the fan-out found, then `orderInvalidationsByDependencies` topologically orders the result — treating the position it was handed as a priority, so a dependency edge wins and everything else keeps the order above. Combine three signals to pin it down: + +1. The bottom row's `url` (max `writeSeq`) is the last-completed file. 2. The worker log's last `begin fused visit of file ` line for the job (visit-file.ts line 108, `index-runner` logger, debug level) names the file the visit _started_ on. If there's no matching `completed fused visit of file ` line, that's where the worker froze. 3. The bottom row's `currentlyEvaluatingModule` / `recentModuleEvaluations[0].url` / `inFlightModuleImports[]` say _which_ module inside that visit was the stall point — same field semantics as Mode A. @@ -542,14 +601,21 @@ To read which row would have been visited next from the working table (rows alre ```sql -- Tombstones the batch inserted but hasn't yet rewritten with content. --- Filtered to the batch's realm_version so older tombstones don't leak --- in. Sort lexically (close to the actual visit order — see --- sortInvalidations). +-- Filtered to the batch's generation so older tombstones don't leak +-- in. A tombstone is written by `invalidate()` before the pass visits +-- anything, so it carries that pass's invalidationId and indexedAt but +-- no writeSeq — it took no position in the write order, and a visited +-- URL's row overwrites it. So a NULL writeSeq is exactly what +-- identifies an un-visited URL here. Sort lexically: it is only an +-- approximation of the planned order (see the three ordering steps +-- above), but the URLs the write named are the ones already gone from +-- this list, so what remains is dep closure. SELECT url, type, file_alias, is_deleted FROM boxel_index_working WHERE realm_url = '' - AND realm_version = + AND generation = AND is_deleted = TRUE + AND diagnostics->>'writeSeq' IS NULL ORDER BY url ASC; ``` @@ -620,9 +686,9 @@ cw --profile claude-staging --region us-east-1 tail -b 2h \ A short rubric for the most common shapes: -- **High confidence the stall is at file X**: the bottom row of `boxel_index_working` (max `indexedAt` for the batch's `invalidationId`) is X **AND** the worker's last `begin fused visit of file X` line has no matching `completed fused visit of file X` line **AND** the bottom row's `recentModuleEvaluations[0].url` (or `currentlyEvaluatingModule` / `inFlightModuleImports[0]`) is a module under X. Treat the row's `diagnostics` as a Mode A capture and walk the [Classify in one pass](#classify-in-one-pass) table. +- **High confidence the stall is at file X**: the bottom row of `boxel_index_working` (max `writeSeq` for the batch's `invalidationId` — not max `indexedAt`, which a single buffered upsert gives a whole flush of rows identically) is X **AND** the worker's last `begin fused visit of file X` line has no matching `completed fused visit of file X` line **AND** the bottom row's `recentModuleEvaluations[0].url` (or `currentlyEvaluatingModule` / `inFlightModuleImports[0]`) is a module under X. Treat the row's `diagnostics` as a Mode A capture and walk the [Classify in one pass](#classify-in-one-pass) table. - **Medium confidence**: only two of the three signals agree. Most often the worker log is the dropout — debug-level logging wasn't on. Promote `index-runner` to debug and trigger a follow-up reindex to validate. -- **Low confidence — the runner stalled before any per-file work**: `boxel_index_working` has no rows for this batch's `invalidationId` (no row stamped with the batch UUID, no `is_deleted = TRUE` tombstones at the batch's `realm_version`). The worker is still in **invalidation discovery** — either the mtime walk (no `discovering invalidations in dir` line yet) or the consumer fan-out (the `discovering` line is there but no per-file visit-start lines). Look at the worker's `index-perf` `time to get file system mtimes` / `time to invalidate` lines — if those are missing too, you're stuck in the realm-server fetch (`reader.mtimes()` → `_mtimes` HTTP call) or in `Batch.invalidate`'s own jsonb-containment SQL (`itemsThatReference`). Then go look at what _should_ have been in the seed but wasn't — cross-check the EFS file listing against the realm's `boxel_index.last_modified` per step 3. +- **Low confidence — the runner stalled before any per-file work**: `boxel_index_working` has no rows for this batch's `invalidationId` (no row stamped with the batch UUID, no `is_deleted = TRUE` tombstones at the batch's `generation`). The worker is still in **invalidation discovery** — either the mtime walk (no `discovering invalidations in dir` line yet) or the consumer fan-out (the `discovering` line is there but no per-file visit-start lines). Look at the worker's `index-perf` `time to get file system mtimes` / `time to invalidate` lines — if those are missing too, you're stuck in the realm-server fetch (`reader.mtimes()` → `_mtimes` HTTP call) or in `Batch.invalidate`'s own jsonb-containment SQL (`itemsThatReference`). Then go look at what _should_ have been in the seed but wasn't — cross-check the EFS file listing against the realm's `boxel_index.last_modified` per step 3. - **Confirm a "rejected" job actually failed cleanly**: `jobs.status = 'rejected'` should pair with the matching reservation's `completed_at IS NOT NULL`. If `completed_at IS NULL`, the worker bailed before its finalize transaction (see `attemptJobFinalize` in `packages/postgres/job-finalize.ts`); the reservation's `locked_until` will eventually expire and another worker can claim it. The actual error is in **`jobs.result`** (jsonb). When the worker's `await job.run(...)` throws, `pg-queue.ts` does `result = flattenErrorForJsonb(err); newStatus = 'rejected';` and the finalize UPDATE writes both into the row. Read it directly: @@ -1412,13 +1478,33 @@ LIMIT 20; ## 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. +`diagnostics` carries `RenderTimeoutDiagnostics` (defined in `packages/runtime-common/index.ts`) plus the write-side stamps `invalidationId` / `indexedAt` / `writeSeq` and the HTTP id `requestId`. The three write-side stamps are on every live row of either channel; 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. ```jsonc { "requestId": "b14e…", // single ID across client/manager/prerender-server - "invalidationId": "a3e1…", // single ID across every row written by the same Batch.invalidate() - "indexedAt": 1776964391615, // wall-clock ms when IndexWriter.updateEntry ran + "invalidationId": "a3e1…", // single ID across every row of one invalidation fan-out. + // Minted when the Batch is created and refreshed by each + // invalidate() call, and an index pass invalidates once, so + // in practice it covers the batch too. The prerender_html + // job an index pass spawns is its own batch with its own id + // — join the channels on url, not on this. + "indexedAt": 1776964391615, // wall-clock ms when the row was written. Millisecond + // resolution, and a buffered multi-row upsert stamps a + // whole flush identically — so this CANNOT order two rows + // of the same pass. Use writeSeq for that. + "writeSeq": 0, // 0-based position of this row in its batch's write order. + // An incremental index pass writes the URLs the triggering + // write named before the dependents its fan-out found, so + // the lowest sequences in a fan-out are its targets — + // except that modules are always written before instances + // and a recorded dependency still comes before what + // depends on it. A card instance contributes two rows + // (file, instance) written back to back; a module has only + // a file row. Absent on a tombstone — a tombstone lands + // before the pass visits anything and a visited URL's row + // overwrites it, so a NULL here on an is_deleted row is + // what identifies a URL the pass never reached. "priority": 10, // worker-job priority that produced this render. Index // visits carry 10 (userInitiatedPriority) or 1 // (systemInitiatedPriority); the prerender-html render diff --git a/packages/realm-server/tests/index-visit-order-test.ts b/packages/realm-server/tests/index-visit-order-test.ts new file mode 100644 index 00000000000..9dc854ac1dd --- /dev/null +++ b/packages/realm-server/tests/index-visit-order-test.ts @@ -0,0 +1,355 @@ +import QUnit from 'qunit'; +const { module, test } = QUnit; +import { basename } from 'path'; +import type { VirtualNetwork } from '@cardstack/runtime-common/virtual-network'; +import type { DependencyIndexRow } from '@cardstack/runtime-common'; +import { prioritizeWrittenURLs } from '@cardstack/runtime-common/index-runner'; +import { IndexRunnerDependencyManager } from '@cardstack/runtime-common/index-runner/dependency-resolver'; + +const realmURL = 'http://example.com/realm/'; + +let urls = (...paths: string[]) => + paths.map((path) => new URL(`${realmURL}${path}`)); +let paths = (result: URL[]) => + result.map((url) => url.href.slice(realmURL.length)); + +// A VirtualNetwork stand-in that resolves references with the platform URL +// parser. Invalidation ordering only reaches it to canonicalize a `deps` +// entry, and the fixtures below write absolute hrefs, so resolution is the +// identity here. +function stubNetwork(): VirtualNetwork { + return { + isRegisteredPrefix() { + return false; + }, + resolveURL(reference: string, relativeTo: URL | string | undefined) { + return new URL(reference, relativeTo ?? undefined); + }, + unresolveURL(url: string) { + return url; + }, + } as unknown as VirtualNetwork; +} + +// A dependency manager whose only live input is the `deps` graph under test. +// Everything else on the ordering path — the definition cache, the +// index-backed error fan-out — is unreachable from +// `orderInvalidationsByDependencies`. +function orderingOver( + deps: Record, +): (invalidations: URL[]) => Promise { + let manager = new IndexRunnerDependencyManager({ + realmURL: new URL(realmURL), + virtualNetwork: stubNetwork(), + async readDefinitionCacheEntries() { + return {}; + }, + async getDependencyRows() { + return []; + }, + async getOrderingDependencyRows(requested: string[]) { + // A URL with no entry here is one the index holds no `deps` row for, + // which is how the real projection reports it. Ordering reads only + // `url` and `deps`; `type` is carried for the projection's shape. + return requested + .filter((url) => deps[url]) + .map( + (url) => + ({ + url, + type: url.endsWith('.json') ? 'instance' : 'module', + deps: deps[url]!.map((dep) => `${realmURL}${dep}`), + }) as Pick, + ); + }, + getInvalidations() { + return []; + }, + }); + return (invalidations: URL[]) => + manager.orderInvalidationsByDependencies(invalidations); +} + +module(basename(import.meta.filename), function () { + module('prioritizeWrittenURLs', function () { + test('hoists the written URLs, keeping the order they were written in', function (assert) { + assert.deepEqual( + paths( + prioritizeWrittenURLs( + urls('aaa.json', 'bbb.json', 'yyy.json', 'zzz.json'), + urls('zzz.json', 'yyy.json'), + new URL(realmURL), + ), + ), + ['zzz.json', 'yyy.json', 'aaa.json', 'bbb.json'], + 'the targets lead in write order and the dependents keep theirs', + ); + }); + + test('ignores a written URL the invalidation set does not contain', function (assert) { + assert.deepEqual( + paths( + prioritizeWrittenURLs( + urls('aaa.json', 'bbb.json'), + urls('elsewhere.json'), + new URL(realmURL), + ), + ), + ['aaa.json', 'bbb.json'], + 'a written URL the fan-out recorded under another name changes nothing', + ); + }); + + test('emits each URL once when a write names the same URL twice', function (assert) { + assert.deepEqual( + paths( + prioritizeWrittenURLs( + urls('aaa.json', 'zzz.json'), + urls('zzz.json', 'zzz.json'), + new URL(realmURL), + ), + ), + ['zzz.json', 'aaa.json'], + 'a repeated target is hoisted once, not duplicated', + ); + }); + + test('never hoists a target instance ahead of a target module', function (assert) { + // One job naming a brand-new instance and the module it adopts from — + // a coalesced pair, or a write the module-then-instance gate did not + // split. The instance was written first, but no persisted `deps` row + // joins them yet, so nothing downstream can restore module-first: the + // hoist has to preserve it. + assert.deepEqual( + paths( + prioritizeWrittenURLs( + urls('card.json', 'person.gts'), + urls('card.json', 'person.gts'), + new URL(realmURL), + ), + ), + ['person.gts', 'card.json'], + 'the module keeps its class priority over the instance that adopts from it', + ); + }); + + test('never leads with a target instance ahead of a module it did not name', function (assert) { + // The write named only the instance; the module reached the fan-out as + // a dependent. Visit class is not a preference between targets — an + // instance whose module has no file entry yet cannot render at all — so + // being the target does not buy the instance a place ahead of it. + assert.deepEqual( + paths( + prioritizeWrittenURLs( + urls('card.json', 'person.gts'), + urls('card.json'), + new URL(realmURL), + ), + ), + ['person.gts', 'card.json'], + 'the dependent module is still visited before the target instance', + ); + }); + + test('keeps a target realm config at the head of the target group', function (assert) { + assert.deepEqual( + paths( + prioritizeWrittenURLs( + urls('aaa.json', 'realm.json', 'zzz.json'), + urls('zzz.json', 'realm.json'), + new URL(realmURL), + ), + ), + ['realm.json', 'zzz.json', 'aaa.json'], + 'the realm config leads the targets, which lead the dependents', + ); + }); + + test('passes a single-URL invalidation set through untouched', function (assert) { + let single = urls('zzz.json'); + assert.strictEqual( + prioritizeWrittenURLs(single, urls('zzz.json'), new URL(realmURL)), + single, + 'a set of one has no order to decide', + ); + }); + }); + + // The visit order an incremental pass ends up with is the composition of + // three steps: `sortInvalidations` (which, for a set of sibling `.json` + // instances, is a lexical sort — the starting order in each case below), + // then `prioritizeWrittenURLs`, then the topological ordering. These pin + // the composition's outcome, so a change to any one of the three that + // breaks target-first ordering fails here. + module('a written URL is visited before its dependents', function () { + test('a dependency edge still overrules the hoist', async function (assert) { + // The written instance adopts from the written module, so the module's + // file entry has to exist before the instance renders. Write order says + // instance-then-module; the dependency graph says otherwise and wins. + let order = orderingOver({ + [`${realmURL}zzz.json`]: ['person.gts'], + }); + assert.deepEqual( + paths( + await order( + prioritizeWrittenURLs( + urls('person.gts', 'zzz.json'), + urls('zzz.json', 'person.gts'), + new URL(realmURL), + ), + ), + ), + ['person.gts', 'zzz.json'], + 'the dependency is visited first even though it was written second', + ); + }); + + test('a dependent no persisted deps row connects to its target loses the lexical race', async function (assert) { + // `aaa.json` is in the fan-out but the index holds no `deps` row for it + // — the state between a link being written and that row being + // reindexed. With no edge to order them, lexical order alone would put + // the dependent first. + let order = orderingOver({}); + assert.deepEqual( + paths( + await order( + prioritizeWrittenURLs( + urls('aaa.json', 'bbb.json', 'zzz.json'), + urls('zzz.json'), + new URL(realmURL), + ), + ), + ), + ['zzz.json', 'aaa.json', 'bbb.json'], + 'the target leads and the dependents follow in their own order', + ); + }); + + test('a target inside a dependency cycle is visited before its dependents', async function (assert) { + // `zzz` and `aaa` link to each other, so those two are the cycle; `bbb` + // links to `zzz` and merely sits behind it, keeping its edge and so + // still waiting for `zzz`. Between the two cycle members no order is + // satisfiable, so priority decides — and without the hoist that hands + // it to lexically-first `aaa`, putting the target second. + let order = orderingOver({ + [`${realmURL}aaa.json`]: ['zzz.json'], + [`${realmURL}bbb.json`]: ['zzz.json'], + [`${realmURL}zzz.json`]: ['aaa.json'], + }); + assert.deepEqual( + paths(await order(urls('aaa.json', 'bbb.json', 'zzz.json'))), + ['aaa.json', 'zzz.json', 'bbb.json'], + 'the cycle member that arrived first wins, and the target lands second', + ); + assert.deepEqual( + paths( + await order( + prioritizeWrittenURLs( + urls('aaa.json', 'bbb.json', 'zzz.json'), + urls('zzz.json'), + new URL(realmURL), + ), + ), + ), + ['zzz.json', 'aaa.json', 'bbb.json'], + 'leading with the target puts it first', + ); + }); + + test('a target stranded in a cycle still outranks a dependent with no edge', async function (assert) { + // The mixed graph: `zzz` (the target) and `aaa` link to each other, so + // both are stranded in a cycle, while `ddd` is in the fan-out with no + // persisted `deps` row of its own and so nothing holding it back. + // Ranking the cycle's members only after every schedulable URL would + // put the target behind `ddd`; dropping the cycle's own edges lets + // priority decide, which is all a cycle's order can be decided by + // anyway. + let order = orderingOver({ + [`${realmURL}aaa.json`]: ['zzz.json'], + [`${realmURL}zzz.json`]: ['aaa.json'], + }); + assert.deepEqual( + paths( + await order( + prioritizeWrittenURLs( + urls('aaa.json', 'ddd.json', 'zzz.json'), + urls('zzz.json'), + new URL(realmURL), + ), + ), + ), + ['zzz.json', 'aaa.json', 'ddd.json'], + 'the target leads even though a cycle strands it and another dependent is ready', + ); + }); + + test('a URL behind a cycle still waits for the cycle member it depends on', async function (assert) { + // `one.js` and `two.js` import each other, and `card.json` adopts from + // `one.js`. Only the two modules are in the cycle; `card.json` merely + // sits behind it. Dropping every edge out of a cycle member would free + // `card.json` to render before `one.js` had a file entry — the edge + // that leaves the cycle is the one that must survive. + let order = orderingOver({ + [`${realmURL}one.js`]: ['two.js'], + [`${realmURL}two.js`]: ['one.js'], + [`${realmURL}card.json`]: ['one.js'], + }); + let visited = paths( + await order( + prioritizeWrittenURLs( + urls('card.json', 'one.js', 'two.js'), + urls('card.json'), + new URL(realmURL), + ), + ), + ); + assert.deepEqual( + visited, + ['one.js', 'two.js', 'card.json'], + 'both modules are visited before the instance that adopts from one of them', + ); + }); + + test('an acyclic set is unaffected by the cycle handling', async function (assert) { + // Dropping the edges inside a cycle removes nothing from an acyclic + // graph, which therefore keeps exactly the order it always had: + // dependencies first, priority breaking every tie. + let order = orderingOver({ + [`${realmURL}aaa.json`]: ['person.gts'], + [`${realmURL}bbb.json`]: ['person.gts'], + [`${realmURL}zzz.json`]: ['person.gts'], + }); + assert.deepEqual( + paths( + await order(urls('aaa.json', 'bbb.json', 'person.gts', 'zzz.json')), + ), + ['person.gts', 'aaa.json', 'bbb.json', 'zzz.json'], + 'the dependency is visited first, then the dependents in priority order', + ); + }); + + test('a batch is visited targets-first, then dependents', async function (assert) { + // Two targets, each in a cycle with one of the dependents, and each + // sorting after its own dependent lexically. + let order = orderingOver({ + [`${realmURL}aaa.json`]: ['zzz.json'], + [`${realmURL}bbb.json`]: ['yyy.json'], + [`${realmURL}yyy.json`]: ['bbb.json'], + [`${realmURL}zzz.json`]: ['aaa.json'], + }); + assert.deepEqual( + paths( + await order( + prioritizeWrittenURLs( + urls('aaa.json', 'bbb.json', 'yyy.json', 'zzz.json'), + urls('yyy.json', 'zzz.json'), + new URL(realmURL), + ), + ), + ), + ['yyy.json', 'zzz.json', 'aaa.json', 'bbb.json'], + 'every target is visited before any dependent', + ); + }); + }); +}); diff --git a/packages/realm-server/tests/prerender-html-split-test.ts b/packages/realm-server/tests/prerender-html-split-test.ts index 0ffefdb2e99..25d4d27c132 100644 --- a/packages/realm-server/tests/prerender-html-split-test.ts +++ b/packages/realm-server/tests/prerender-html-split-test.ts @@ -615,6 +615,29 @@ module(basename(import.meta.filename), function () { return rows[0]; } + // Every live row on either channel carries the three write-side stamps + // in its `diagnostics` column (see `Diagnostics`). Assert they are there, + // then return the rest of the blob so a render-side assertion can compare + // exactly what the render produced. Not for `error_doc.diagnostics`: that + // mirror carries the render's own diagnostics only. + function withoutWriteSideStamps( + diagnostics: Record | null | undefined, + label: string, + assert: Assert, + ): Record { + assert.ok(diagnostics, `${label} carries a diagnostics blob`); + let rest: Record = { ...(diagnostics ?? {}) }; + for (let key of ['invalidationId', 'indexedAt', 'writeSeq']) { + assert.notStrictEqual( + rest[key], + undefined, + `${label} is stamped with ${key}`, + ); + delete rest[key]; + } + return rest; + } + function stubReader(contents: Map): Reader { return { async readFile(url: URL) { @@ -821,7 +844,7 @@ module(basename(import.meta.filename), function () { let row = await productionRow(url); assert.deepEqual( - row.diagnostics, + withoutWriteSideStamps(row.diagnostics, 'the rendered row', assert), diagnostics as Record, 'the render diagnostics ride the row through the swap', ); @@ -860,14 +883,14 @@ module(basename(import.meta.filename), function () { 'the last-known-good HTML is preserved through the error cycle', ); assert.deepEqual( - row.diagnostics, + withoutWriteSideStamps(row.diagnostics, 'the error row', assert), failing as Record, "the failing render's diagnostics land on the row — not the last-known-good render's", ); assert.deepEqual( row.error_doc?.diagnostics, failing as Record, - 'the same payload is mirrored onto the error doc', + 'the same payload is mirrored onto the error doc, without the stamps', ); }); @@ -971,9 +994,152 @@ module(basename(import.meta.filename), function () { prerenderHtmlRequestId: 'render-req-9', }; let instanceRow = await productionRow(cardURL, 'instance'); - assert.deepEqual(instanceRow.diagnostics, expected); + assert.deepEqual( + withoutWriteSideStamps( + instanceRow.diagnostics, + 'the instance row', + assert, + ), + expected, + ); let fileRow = await productionRow(cardURL, 'file'); - assert.deepEqual(fileRow.diagnostics, expected); + assert.deepEqual( + withoutWriteSideStamps(fileRow.diagnostics, 'the file row', assert), + expected, + ); + assert.strictEqual( + instanceRow.diagnostics?.invalidationId, + fileRow.diagnostics?.invalidationId, + "both of the URL's rows are attributed to the pass that wrote them", + ); + }); + + test('the pass stamps every rendering with its own grouping id and write order', async function (assert) { + // The render channel is its own fan-out: an operator asking "what did + // this prerender_html job render, and in what order?" reads the two + // stamps below off the rows, the same way they read an index pass's + // fan-out. The grouping id is per batch, so it is the render channel's + // own key and does not equal the spawning index pass's — the two + // channels join on url. + let urls = [ + `${testRealm}zzz.json`, + `${testRealm}aaa.json`, + `${testRealm}bbb.json`, + ]; + let batch = await makeBatch(4); + await batch.seedPrerenderedHtmlInvalidations( + urls.map((url) => ({ url, operation: 'update' as const })), + ); + for (let [i, url] of urls.entries()) { + await batch.updatePrerenderedHtmlEntry(new URL(url), { + type: 'instance', + isolatedHtml: `

${i}

`, + deps: [], + // Only the middle rendering reports any diagnostics of its own, so + // this also pins that a rendering with none is still attributable. + ...(i === 1 ? { diagnostics: { renderElapsedMs: 7 } } : {}), + }); + } + await batch.done(); + + let rows = (await adapter.execute( + `SELECT url, diagnostics FROM prerendered_html + WHERE realm_url = $1 AND type = 'instance' + ORDER BY (diagnostics->>'writeSeq')::int`, + { bind: [testRealm] }, + )) as { url: string; diagnostics: Record | null }[]; + + assert.deepEqual( + rows.map((row) => row.url), + urls, + 'writeSeq orders the renderings the way the pass wrote them, not lexically', + ); + assert.deepEqual( + rows.map((row) => row.diagnostics?.writeSeq), + [0, 1, 2], + 'the sequence is 0-based and gapless across the pass', + ); + assert.strictEqual( + new Set(rows.map((row) => row.diagnostics?.invalidationId)).size, + 1, + 'one grouping id covers the whole pass', + ); + assert.strictEqual( + rows[1]?.diagnostics?.renderElapsedMs, + 7, + "the stamps merge around a rendering's own diagnostics rather than replacing them", + ); + }); + + test('the index channel stamps each write with its position, and a rewrite keeps the first', async function (assert) { + // The visit loop hands its rows to a write-behind buffer that drains + // them in one multi-row upsert, so a row's position has to be taken + // where it entered the buffer: `indexedAt` alone cannot separate rows + // one drain wrote, and the drain itself collapses two writes of the + // same row into one. A row written again keeps the position its first + // write took — on either side of a flush, since a rewrite can land on + // either side of one — while its contents are the last write's. The + // positions stay gapless: the rewrites below consume none of their own. + let batch = await indexWriter.createBatch( + new URL(testRealm), + virtualNetwork, + jobInfo(), + ); + let file = (lastModified: number) => ({ + type: 'file' as const, + lastModified, + resourceCreatedAt: lastModified, + deps: new Set(), + }); + let url = (path: string) => new URL(`${testRealm}${path}`); + await batch.invalidate([url('zzz.gts'), url('aaa.gts'), url('bbb.gts')]); + await batch.bufferEntry(url('zzz.gts'), file(1)); + await batch.bufferEntry(url('aaa.gts'), file(2)); + // Rewritten before the buffer drains — the same visit, correcting the + // row it already wrote. + await batch.bufferEntry(url('zzz.gts'), file(3)); + await batch.flushWriteBuffer(); + // Rewritten again after the drain, so the position has to outlive the + // buffer that carried it. + await batch.bufferEntry(url('zzz.gts'), file(4)); + await batch.bufferEntry(url('bbb.gts'), file(5)); + await batch.done(); + + let rows = (await adapter.execute( + `SELECT url, last_modified, + diagnostics->>'writeSeq' AS seq, + diagnostics->>'invalidationId' AS invalidation_id + FROM boxel_index + WHERE realm_url = $1 AND type = 'file' + ORDER BY (diagnostics->>'writeSeq')::int`, + { bind: [testRealm] }, + )) as { + url: string; + last_modified: string | number | null; + seq: string | null; + invalidation_id: string | null; + }[]; + + assert.deepEqual( + rows.map((row) => row.url), + [url('zzz.gts').href, url('aaa.gts').href, url('bbb.gts').href], + 'writeSeq replays the order the pass wrote its rows, not the lexical order', + ); + assert.deepEqual( + rows.map((row) => row.seq), + ['0', '1', '2'], + 'the rewrites kept zzz.gts at position 0 and consumed no position of their own', + ); + assert.strictEqual( + Number(rows[0]?.last_modified), + 4, + "the row's contents are the last write's, even though its position is the first write's", + ); + assert.strictEqual( + new Set(rows.map((row) => row.invalidation_id)).size, + 1, + 'one grouping id covers the whole pass', + ); }); test('a retry resumes rows the prior attempt rendered instead of tombstoning them', async function (assert) { diff --git a/packages/realm-server/tests/target-first-index-ordering-test.ts b/packages/realm-server/tests/target-first-index-ordering-test.ts new file mode 100644 index 00000000000..7accd6e8b06 --- /dev/null +++ b/packages/realm-server/tests/target-first-index-ordering-test.ts @@ -0,0 +1,343 @@ +import QUnit from 'qunit'; +const { module, test } = QUnit; +import { basename } from 'path'; + +import { rri, SupportedMimeType } from '@cardstack/runtime-common'; +import type { DBAdapter, Realm } from '@cardstack/runtime-common'; +import { + setupPermissionedRealmCached, + createJWT, + withRealmPath, + type RealmRequest, +} from './helpers/index.ts'; +import { + depsForIndexEntry, + settlePrerenderHtmlJobs, +} from './helpers/indexing.ts'; + +const testRealm = new URL('http://127.0.0.1:4445/test/'); + +// One card definition with a `friend` link that its templates RENDER, and +// that is deliberately NOT `searchable`. Rendering is what records the link +// target as a dependency of the card that links to it, and those recorded +// dependencies are what the invalidation walk reads to find a written URL's +// dependents. A link the templates never read is not captured, however the +// field is declared, and a card with no recorded dependency on the target +// never reaches the pass's fan-out at all. +// +// Leaving `searchable` off is what makes these scenarios exercise the +// ordering under test. A `searchable` link is followed by the search-doc +// walk, whose collected targets the meta route unions into the index +// channel's own `deps` — an edge the dependency ordering reads, which would +// put the target first on its own. Recorded only by the render, the edge +// lands on the render channel, which the invalidation walk reads and the +// ordering does not: the fan-out still finds the dependents, and nothing but +// the write's own URL can put the target ahead of them. +// +// `friend` renders as `atom`, which reads only `firstName`, so the render +// follows the link exactly one hop rather than recursing through the graph. +function makeFileSystem() { + return { + 'person.gts': ` + import { contains, field, linksTo, CardDef, Component } from "@cardstack/base/card-api"; + import StringField from "@cardstack/base/string"; + + export class Person extends CardDef { + @field firstName = contains(StringField); + @field friend = linksTo(() => Person); + static atom = class Atom extends Component { + + } + static isolated = class Isolated extends Component { + + } + static embedded = class Embedded extends Component { + + } + static fitted = class Fitted extends Component { + + } + } + `, + }; +} + +module(basename(import.meta.filename), function (hooks) { + let realm: Realm; + let testDbAdapter: DBAdapter; + let request: RealmRequest; + + setupPermissionedRealmCached(hooks, { + mode: 'beforeEach', + realmURL: testRealm, + permissions: { + '*': ['read', 'write'], + '@node-test_realm:localhost': ['read', 'write', 'realm-owner'], + }, + fileSystem: makeFileSystem(), + onRealmSetup(args) { + realm = args.testRealm; + testDbAdapter = args.dbAdapter; + request = withRealmPath(args.request, testRealm); + }, + }); + + // A push, then both channels drained: the index job so its rows are + // written and attributed to a finished pass, and the prerender_html job it + // spawns so the next push starts from a quiet queue. Every `/_atomic` + // response is 201, add and update alike. + async function push( + assert: Assert, + label: string, + operations: Record[], + ): Promise { + let response = await request + .post('/_atomic') + .set('Accept', SupportedMimeType.JSONAPI) + .set( + 'Authorization', + `Bearer ${createJWT(realm, 'user', ['read', 'write'])}`, + ) + .send(JSON.stringify({ 'atomic:operations': operations })); + assert.strictEqual(response.status, 201, label); + await realm.incrementalIndexing(); + await settlePrerenderHtmlJobs(testDbAdapter, realm.url); + } + + // The dependencies an instance records across both channels — the index + // visit's own edges plus the ones only a format render discovers — which is + // the union the invalidation walk consults. A dependent reaches a pass's + // fan-out only by naming the written URL somewhere in here, so every + // scenario asserts this before it asserts an order: a fan-out that came + // back empty would otherwise read as an ordering failure. + async function depsOf(path: string): Promise { + return depsForIndexEntry(testDbAdapter, `${realm.url}${path}`); + } + + async function assertDependsOnTarget( + assert: Assert, + dependent: string, + target: string, + ): Promise { + let deps = await depsOf(dependent); + assert.ok( + deps.some((dep) => dep === `${realm.url}${target}`), + `precondition: ${dependent} records a dependency on ${target} (deps: ${JSON.stringify(deps)})`, + ); + } + + // Every stamped row in the realm, newest pass first. Carried into the + // ordering assertions' messages so a failure names what the pass actually + // wrote rather than only what it did not. + async function stampedRows(): Promise { + let rows = (await testDbAdapter.execute( + `select url, type, + diagnostics->>'invalidationId' as invalidation_id, + diagnostics->>'writeSeq' as seq, + diagnostics->>'indexedAt' as indexed_at, + is_deleted + from boxel_index + where realm_url = $1 + order by (diagnostics->>'indexedAt')::bigint desc nulls last, url`, + { bind: [realm.url] }, + )) as { + url: string; + type: string; + invalidation_id: string | null; + seq: string | null; + indexed_at: string | null; + is_deleted: boolean | null; + }[]; + return rows + .map( + (row) => + `${row.url.slice(realm.url.length)}/${row.type} seq=${row.seq ?? '-'} ` + + `pass=${(row.invalidation_id ?? '-').slice(0, 8)} at=${row.indexed_at ?? '-'}` + + `${row.is_deleted ? ' deleted' : ''}`, + ) + .join('; '); + } + + function person( + op: 'add' | 'update', + href: string, + firstName: string, + friendHref?: string, + ): Record { + return { + op, + href, + data: { + type: 'card', + attributes: { firstName }, + ...(friendHref + ? { relationships: { friend: { links: { self: friendHref } } } } + : {}), + meta: { adoptsFrom: { module: rri('./person'), name: 'Person' } }, + }, + }; + } + + // The write order of the most recent indexing pass, read back off the rows + // it wrote: `diagnostics.invalidationId` groups a pass's rows and + // `diagnostics.writeSeq` orders them. Reduced to each URL's lowest sequence + // because a visit writes both a `file` and an `instance` row, and the + // question is when the URL's visit started writing. Scoped to the pass with + // the newest `indexedAt`, so the fixture build's own pass — and the earlier + // pushes each scenario needs to set its graph up — cannot bleed in. + async function writeOrderOfLatestPass(): Promise { + let rows = (await testDbAdapter.execute( + `select url, min((diagnostics->>'writeSeq')::int) as seq + from boxel_index + where realm_url = $1 + and diagnostics->>'writeSeq' is not null + and diagnostics->>'invalidationId' = ( + select diagnostics->>'invalidationId' + from boxel_index + where realm_url = $1 + and diagnostics->>'writeSeq' is not null + order by (diagnostics->>'indexedAt')::bigint desc, url + limit 1 + ) + group by url + order by seq`, + { bind: [realm.url] }, + )) as { url: string; seq: number | string }[]; + return rows.map((row) => row.url); + } + + test('a pass stamps every row it writes with its sequence and the pass it belongs to', async function (assert) { + assert.timeout(120_000); + + await push(assert, 'the card is created', [ + person('add', 'solo.json', 'Solo'), + ]); + + let rows = (await testDbAdapter.execute( + `select type, diagnostics->>'writeSeq' as seq, + diagnostics->>'invalidationId' as invalidation_id + from boxel_index + where url = $1 + order by type`, + { bind: [`${realm.url}solo.json`] }, + )) as { + type: string; + seq: string | null; + invalidation_id: string | null; + }[]; + + assert.strictEqual( + rows.length, + 2, + 'the visit wrote the URL a file row and an instance row', + ); + for (let row of rows) { + let seq = row.seq === null ? NaN : Number(row.seq); + assert.true( + Number.isInteger(seq), + `the ${row.type} row carries an integer writeSeq (got ${row.seq})`, + ); + assert.ok( + row.invalidation_id, + `the ${row.type} row names the pass that wrote it`, + ); + } + assert.strictEqual( + new Set(rows.map((row) => row.invalidation_id)).size, + 1, + 'both rows are attributed to the same pass', + ); + }); + + test("a write's own row is written before the dependents its fan-out found", async function (assert) { + assert.timeout(300_000); + + // `aaa` and `bbb` both link to `zzz` and render the link, so writing + // `zzz` fans out to all three, and `zzz` sorts last of the three. The + // target links to neither of them, so no dependency of its own pins it + // ahead: what the pass falls back on is the order the URLs arrived in, + // where the target came last. Leading with the write's own URL is the + // only thing that puts it first. + await push(assert, 'the target is created', [ + person('add', 'zzz.json', 'Zeta'), + ]); + await push(assert, 'the dependents are created', [ + person('add', 'aaa.json', 'Alpha', './zzz'), + person('add', 'bbb.json', 'Beta', './zzz'), + ]); + + // Both dependents have to name the target for the fan-out to reach them. + await assertDependsOnTarget(assert, 'aaa.json', 'zzz.json'); + await assertDependsOnTarget(assert, 'bbb.json', 'zzz.json'); + + // The pass under test: one write naming `zzz.json`. + await push(assert, 'the target is written', [ + person('update', 'zzz.json', 'Zeta the Second'), + ]); + + let order = await writeOrderOfLatestPass(); + let rows = await stampedRows(); + assert.deepEqual( + [...order].sort(), + [`${realm.url}aaa.json`, `${realm.url}bbb.json`, `${realm.url}zzz.json`], + `the pass visited the target and both dependents (order: ${order.join(', ')}) (rows: ${rows})`, + ); + assert.strictEqual( + order[0], + `${realm.url}zzz.json`, + `the target's row is written first (order: ${order.join(', ')})`, + ); + }); + + test('a batch writes every target before any dependent', async function (assert) { + assert.timeout(300_000); + + // Two targets, each with one dependent linking to it, and each sorting + // after both dependents lexically. + await push(assert, 'the targets are created', [ + person('add', 'yyy.json', 'Ypsilon'), + person('add', 'zzz.json', 'Zeta'), + ]); + await push(assert, 'the dependents are created', [ + person('add', 'aaa.json', 'Alpha', './zzz'), + person('add', 'bbb.json', 'Beta', './yyy'), + ]); + + await assertDependsOnTarget(assert, 'aaa.json', 'zzz.json'); + await assertDependsOnTarget(assert, 'bbb.json', 'yyy.json'); + + // The pass under test: one write naming both targets. + await push(assert, 'both targets are written', [ + person('update', 'yyy.json', 'Ypsilon the Second'), + person('update', 'zzz.json', 'Zeta the Second'), + ]); + + let order = await writeOrderOfLatestPass(); + let rows = await stampedRows(); + assert.deepEqual( + [...order].sort(), + [ + `${realm.url}aaa.json`, + `${realm.url}bbb.json`, + `${realm.url}yyy.json`, + `${realm.url}zzz.json`, + ], + `the pass visited both targets and both dependents (order: ${order.join(', ')}) (rows: ${rows})`, + ); + assert.deepEqual( + order.slice(0, 2).sort(), + [`${realm.url}yyy.json`, `${realm.url}zzz.json`], + `both targets are written before either dependent (order: ${order.join(', ')})`, + ); + }); +}); diff --git a/packages/runtime-common/index-runner.ts b/packages/runtime-common/index-runner.ts index 5810a359ecd..baf361b4424 100644 --- a/packages/runtime-common/index-runner.ts +++ b/packages/runtime-common/index-runner.ts @@ -488,6 +488,11 @@ export class IndexRunner { current.batch.invalidations.map((href) => new URL(href)), current.realmURL, ); + invalidations = prioritizeWrittenURLs( + invalidations, + urls, + current.realmURL, + ); invalidations = await current.#dependencyResolver.orderInvalidationsByDependencies( invalidations, @@ -1185,34 +1190,112 @@ function assertURLEndsWithJSON(url: URL): URL { return url; } +// Order the pass's visit list so the URLs the triggering write named — the +// pass's targets — come first, in the order they were written, ahead of the +// dependents the invalidation fan-out discovered. +// +// Visit class outranks being a target (see `visitClassRank`), for targets and +// dependents alike: a module is visited before any instance whether or not +// the write named it, because an instance rendering before the module it +// adopts from has no file entry to render against — a failure, not a stale +// read. Ranking class first is also what carries the target-first guarantee +// through `orderInvalidationsByDependencies`, which treats this order as a +// tie-break priority rather than a fixed sequence: inside a dependency cycle +// it has no satisfiable order to offer and ranks the members by priority +// alone, so a module that arrived behind an instance would stay behind it. +// +// Within one class the targets lead, in the order they were written, then the +// dependents in the order they arrived in. Every URL in a class is either a +// target with its own write position or a dependent with its own arrival +// position, so the comparison is total and the result does not depend on the +// sort being stable. +// +// A recorded dependency edge still overrules all of this downstream. What the +// priority decides is the cases the dependency graph leaves open — a +// dependent no persisted `deps` row connects to its target, and a target +// stranded in a dependency cycle — where the ordering falls back to the +// incoming order and would otherwise be free to leave the target last. +// +// This is a guarantee about the order in which a pass writes its rows, not +// about what a concurrent reader can observe: the pass promotes its whole +// working table in one transaction (`batch.done()`), so no reader ever sees +// one row of a pass ahead of another. +export function prioritizeWrittenURLs( + invalidations: URL[], + written: URL[], + realmURL: URL, +): URL[] { + if (invalidations.length < 2) { + return invalidations; + } + let inFanOut = new Set(invalidations.map((url) => url.href)); + // A written URL missing from the fan-out is one the invalidation walk + // recorded under its node-resolved alias instead. Nothing to rank: the + // dependency graph and the incoming order decide, as they always have. + let writePositions = new Map(); + for (let url of written) { + if (inFanOut.has(url.href) && !writePositions.has(url.href)) { + writePositions.set(url.href, writePositions.size); + } + } + let realmConfigHref = realmConfigHrefFor(realmURL); + let ranked = invalidations.map((url, arrival) => { + let writePosition = writePositions.get(url.href); + return { + url, + visitClass: visitClassRank(url, realmConfigHref), + isDependent: writePosition === undefined ? 1 : 0, + position: writePosition ?? arrival, + }; + }); + ranked.sort( + (a, b) => + a.visitClass - b.visitClass || + a.isDependent - b.isDependent || + a.position - b.position, + ); + return ranked.map(({ url }) => url); +} + +// Visit-class priority, in the order a pass must write the classes: +// +// 0. The realm's RealmConfig card at realm.json — write its +// working-index row first so any /_info query that lands AFTER the +// pass commits (`batch.done()` swaps boxel_index_working into +// boxel_index) sees the RealmConfig overlay and resolves the realm's +// display name. parseRealmInfo's overlay path queries the live +// `boxel_index` table without `useWorkInProgressIndex`, so it cannot +// see realm.json mid-pass; this ordering only guarantees a correct +// answer at and after the pass-end commit (and on subsequent +// passes). Host-side prerender caching of stale realmInfo (see +// RealmResource.fetchInfo's `dropTask` short-circuit) is a separate +// concern not addressed here. +// 1. Non-.json files (modules, source) — file entries must exist before +// the cards that depend on them are rendered. +// 2. Other .json files. +// +// Class 1 before class 2 is a correctness requirement, not a preference, +// and it holds for a class-2 URL whose dependency on a class-1 URL the index +// has not recorded yet — a brand-new instance and the module it adopts from, +// written by one job. Both orderers below therefore rank by class before +// applying their own tie-break. +function visitClassRank(url: URL, realmConfigHref: string): number { + if (url.href === realmConfigHref) { + return 0; + } + return url.href.endsWith('.json') ? 2 : 1; +} + +function realmConfigHrefFor(realmURL: URL): string { + return new RealmPaths(realmURL).fileURL('realm.json').href; +} + function sortInvalidations(urls: URL[], realmURL: URL): URL[] { - // Visit order priority: - // 1. The realm's RealmConfig card at realm.json — write its - // working-index row first so any /_info query that lands AFTER the - // pass commits (`batch.done()` swaps boxel_index_working into - // boxel_index) sees the RealmConfig overlay and resolves the realm's - // display name. parseRealmInfo's overlay path queries the live - // `boxel_index` table without `useWorkInProgressIndex`, so it cannot - // see realm.json mid-pass; this ordering only guarantees a correct - // answer at and after the pass-end commit (and on subsequent - // passes). Host-side prerender caching of stale realmInfo (see - // RealmResource.fetchInfo's `dropTask` short-circuit) is a separate - // concern not addressed here. - // 2. Non-.json files (modules, source) — file entries must exist before - // the cards that depend on them are rendered. - // 3. Other .json files, sorted lexically for determinism. - let realmConfigHref = new RealmPaths(realmURL).fileURL('realm.json').href; + // Class order (see visitClassRank), then lexical by href for determinism. + let realmConfigHref = realmConfigHrefFor(realmURL); return urls.sort((a, b) => { - let aRealmConfig = a.href === realmConfigHref; - let bRealmConfig = b.href === realmConfigHref; - if (aRealmConfig !== bRealmConfig) { - return aRealmConfig ? -1 : 1; - } - let aJson = a.href.endsWith('.json'); - let bJson = b.href.endsWith('.json'); - if (aJson === bJson) { - return a.href.localeCompare(b.href); - } - return aJson ? 1 : -1; + let rank = + visitClassRank(a, realmConfigHref) - visitClassRank(b, realmConfigHref); + return rank !== 0 ? rank : a.href.localeCompare(b.href); }); } diff --git a/packages/runtime-common/index-runner/dependency-resolver.ts b/packages/runtime-common/index-runner/dependency-resolver.ts index 3342795c1a0..3a32f685210 100644 --- a/packages/runtime-common/index-runner/dependency-resolver.ts +++ b/packages/runtime-common/index-runner/dependency-resolver.ts @@ -99,6 +99,25 @@ export class IndexRunnerDependencyManager { ); } + // Topologically order an invalidation set so a URL is visited after every + // URL it depends on, using the `deps` rows the index has persisted. + // + // The incoming order is the priority: among the URLs whose dependencies + // are all satisfied, the one that arrived earliest goes first. Callers + // therefore express a preference by the order they pass, and get it + // wherever a recorded dependency does not overrule it. The incremental + // pass leads its input with the URLs its triggering write named + // (`prioritizeWrittenURLs`). + // + // A dependency cycle has no topological order, so the edges running + // through one are dropped and its members are scheduled by priority + // alongside everything else (see `#edgesWithinCyclesDropped`). Dropping + // them costs nothing a cycle had not already cost — no order satisfies + // every edge in a cycle — and it is what keeps priority meaningful for a + // URL caught in one: otherwise a cycle member could never be scheduled + // until every acyclic URL had been, however high its priority. A URL that + // merely depends on a cycle member is not itself in the cycle, so its edge + // survives and it still waits. async orderInvalidationsByDependencies(urls: URL[]): Promise { if (urls.length < 2) { return urls; @@ -109,12 +128,10 @@ export class IndexRunnerDependencyManager { let order = new Map(hrefs.map((href, index) => [href, index])); let rows = await this.#getOrderingDependencyRows(hrefs); + // dependency -> the URLs in this set that depend on it. Indegrees are + // derived from these edges by `#kahnByPriority`, over the reduced edge + // set that survives the cycle drop below. let edges = new Map>(); - let indegree = new Map(); - for (let href of hrefs) { - indegree.set(href, 0); - } - for (let row of rows) { if (!byHref.has(row.url)) { continue; @@ -130,25 +147,179 @@ export class IndexRunnerDependencyManager { dependents = new Set(); edges.set(normalized, dependents); } - if (!dependents.has(row.url)) { - dependents.add(row.url); - indegree.set(row.url, (indegree.get(row.url) ?? 0) + 1); + dependents.add(row.url); + } + } + + // Only the edges INSIDE a cycle are unsatisfiable, so only those are + // dropped. Scoping the drop to a strongly-connected component is what + // keeps a URL that merely sits *behind* a cycle waiting for its + // dependency: its incoming edge comes from a cycle member but crosses + // out of that component, so it survives and still orders the pair. The + // condensation of a digraph by its components is a DAG, so what remains + // always schedules completely. + let ordered = this.#kahnByPriority( + hrefs, + this.#edgesWithinCyclesDropped(hrefs, edges), + order, + ); + // Belt and braces: a URL the scheduler somehow still could not place is + // appended rather than dropped, because losing one from the visit list + // would leave its tombstone to be promoted. + if (ordered.length !== hrefs.length) { + let orderedSet = new Set(ordered); + for (let href of hrefs) { + if (!orderedSet.has(href)) { + ordered.push(href); + orderedSet.add(href); } } } + return ordered + .map((href) => byHref.get(href)) + .filter((url): url is URL => Boolean(url)); + } + + // `edges` minus the edges whose endpoints share a strongly-connected + // component of more than one URL — that is, minus exactly the edges a + // dependency cycle runs through. Every other edge, including one leading + // out of a cycle into a URL that depends on it, is preserved. + #edgesWithinCyclesDropped( + hrefs: string[], + edges: Map>, + ): Map> { + let { componentOf, componentSize } = this.#stronglyConnectedComponents( + hrefs, + edges, + ); + let kept = new Map>(); + for (let [dependency, dependents] of edges) { + let component = componentOf.get(dependency); + let inCycle = + component !== undefined && (componentSize.get(component) ?? 1) > 1; + let keptDependents = inCycle + ? new Set( + [...dependents].filter( + (dependent) => componentOf.get(dependent) !== component, + ), + ) + : dependents; + if (keptDependents.size > 0) { + kept.set(dependency, keptDependents); + } + } + return kept; + } + + // Tarjan's strongly-connected components, iterative so a deep dependency + // graph cannot overflow the stack. Two URLs share a component id exactly + // when each is reachable from the other — i.e. they sit in one cycle. A + // URL in no cycle gets a component of its own, of size 1. + #stronglyConnectedComponents( + hrefs: string[], + edges: Map>, + ): { + componentOf: Map; + componentSize: Map; + } { + let visitIndex = new Map(); + let lowLink = new Map(); + let onStack = new Set(); + let componentStack: string[] = []; + let componentOf = new Map(); + let componentSize = new Map(); + let nextIndex = 0; + let nextComponent = 0; + + for (let root of hrefs) { + if (visitIndex.has(root)) { + continue; + } + let frames: { href: string; dependents: string[]; cursor: number }[] = []; + let enter = (href: string) => { + visitIndex.set(href, nextIndex); + lowLink.set(href, nextIndex); + nextIndex++; + componentStack.push(href); + onStack.add(href); + frames.push({ + href, + dependents: [...(edges.get(href) ?? [])], + cursor: 0, + }); + }; + enter(root); + while (frames.length > 0) { + let frame = frames[frames.length - 1]!; + if (frame.cursor < frame.dependents.length) { + let dependent = frame.dependents[frame.cursor++]!; + if (!visitIndex.has(dependent)) { + enter(dependent); + } else if (onStack.has(dependent)) { + lowLink.set( + frame.href, + Math.min(lowLink.get(frame.href)!, visitIndex.get(dependent)!), + ); + } + continue; + } + frames.pop(); + if (lowLink.get(frame.href) === visitIndex.get(frame.href)) { + let component = nextComponent++; + let size = 0; + for (;;) { + let member = componentStack.pop()!; + onStack.delete(member); + componentOf.set(member, component); + size++; + if (member === frame.href) { + break; + } + } + componentSize.set(component, size); + } + let parent = frames[frames.length - 1]; + if (parent) { + lowLink.set( + parent.href, + Math.min(lowLink.get(parent.href)!, lowLink.get(frame.href)!), + ); + } + } + } + return { componentOf, componentSize }; + } + + // Kahn's algorithm with a priority queue keyed on `order`: of the URLs + // whose dependencies are all scheduled, the lowest-`order` one goes next. + #kahnByPriority( + hrefs: string[], + edges: Map>, + order: Map, + ): string[] { + let indegree = new Map(); + for (let href of hrefs) { + indegree.set(href, 0); + } + for (let dependents of edges.values()) { + for (let dependent of dependents) { + indegree.set(dependent, (indegree.get(dependent) ?? 0) + 1); + } + } + + let priorityOf = (href: string) => + order.get(href) ?? Number.MAX_SAFE_INTEGER; let queue = hrefs .filter((href) => (indegree.get(href) ?? 0) === 0) - .sort((a, b) => (order.get(a) ?? 0) - (order.get(b) ?? 0)); - let ordered: string[] = []; + .sort((a, b) => priorityOf(a) - priorityOf(b)); let insertByOrder = (href: string) => { - let priority = order.get(href) ?? Number.MAX_SAFE_INTEGER; + let priority = priorityOf(href); let low = 0; let high = queue.length; while (low < high) { let mid = Math.floor((low + high) / 2); - let midPriority = order.get(queue[mid]!) ?? Number.MAX_SAFE_INTEGER; - if (midPriority <= priority) { + if (priorityOf(queue[mid]!) <= priority) { low = mid + 1; } else { high = mid; @@ -157,6 +328,7 @@ export class IndexRunnerDependencyManager { queue.splice(low, 0, href); }; + let ordered: string[] = []; while (queue.length > 0) { let href = queue.shift()!; ordered.push(href); @@ -168,20 +340,7 @@ export class IndexRunnerDependencyManager { } } } - - if (ordered.length !== hrefs.length) { - let orderedSet = new Set(ordered); - for (let href of hrefs) { - if (!orderedSet.has(href)) { - ordered.push(href); - orderedSet.add(href); - } - } - } - - return ordered - .map((href) => byHref.get(href)) - .filter((url): url is URL => Boolean(url)); + return ordered; } extractDirectRelationshipDeps( diff --git a/packages/runtime-common/index-writer.ts b/packages/runtime-common/index-writer.ts index 6231d8f25de..a2769ecc111 100644 --- a/packages/runtime-common/index-writer.ts +++ b/packages/runtime-common/index-writer.ts @@ -295,9 +295,40 @@ export class Batch { // Write-behind buffer for the index visit loop (see `bufferEntry`). Rows // accumulate here so the prerender tab renders the next file while these // drain; `#writeBufferUrls` mirrors their URLs for the dependency-read - // flush check in `getDependencyRows`. - #writeBuffer: { url: URL; entry: SearchIndexEntry }[] = []; + // flush check in `getDependencyRows`. Each item carries the `seq` it was + // stamped with on the way in, so buffering — which reorders nothing but + // does collapse many rows into one timestamp — cannot blur the write order + // the row records. + #writeBuffer: { url: URL; entry: SearchIndexEntry; seq: number }[] = []; #writeBufferUrls = new Set(); + // Monotonic counter behind `diagnostics.writeSeq`, reset alongside + // `#currentInvalidationId` so the two stamps always describe the same + // fan-out. Advanced where a row enters the write path (`bufferEntry` / + // `updateEntry`) rather than where it is prepared, so the sequence records + // the order the pass produced its rows — which for an index pass is its + // visit order — independent of how the buffer batches the physical + // upserts. Tombstones do not advance it: `invalidate()` writes one for + // every URL in the fan-out before any visit, and a visited URL's row + // overwrites its tombstone, so counting them would leave a gap for every + // URL rather than describe an order. + // + // `#writePositions` holds the position each row has already taken, so a + // row written more than once in a pass keeps its first — the position + // records where in the pass the work on that row began, and a rewrite is + // that same work continuing. Keyed by row rather than by URL (a card's + // `file` and `instance` halves are separate rows), and held for the whole + // fan-out rather than for one buffer drain, because a rewrite can land on + // either side of a flush. A rewrite consumes no position, so a fan-out's + // sequences are gapless. + // + // A retried job is the one case where a promoted generation holds rows + // from two batches: `loadResumedRows` keeps the previous attempt's rows as + // they are, so they retain that attempt's `invalidationId` and its + // sequences, and only the URLs this attempt visits carry the current pair. + // Ordering within one `invalidationId` stays sound; a query that wants the + // whole generation has to union the attempts' ids rather than assume one. + #writeSeq = 0; + #writePositions = new Map(); // Aggregate wall of every physical `boxel_index_working` write in this // batch, surfaced on the job result's `phaseTimings.writeMs`. #writeMs = 0; @@ -981,7 +1012,11 @@ export class Batch { } this.#assertErrorEntryHasMessage(url, entry); this.#invalidations.add(url.href); - this.#writeBuffer.push({ url, entry }); + this.#writeBuffer.push({ + url, + entry, + seq: this.#positionOf(url, rowType(entry)), + }); this.#writeBufferUrls.add(url.href); // Bound memory for long runs of dependency-free files; dependency reads // flush earlier. Renders dwarf the writes, so a forced flush here still @@ -1006,21 +1041,26 @@ export class Batch { let start = Date.now(); try { if (this.#splitPrerenderHtml) { - // Last write wins when the same (url, type) was buffered twice: a - // single multi-row upsert can't touch one conflict target twice. - let deduped = new Map(); + // Last write wins when the same row was buffered twice: a single + // multi-row upsert can't touch one conflict target twice. Only the + // contents are the later write's — both items carry the position the + // row took when the pass first wrote it (see `#positionOf`). + let deduped = new Map< + string, + { url: URL; entry: SearchIndexEntry; seq: number } + >(); for (let item of buffered) { deduped.set(`${item.url.href}|${rowType(item.entry)}`, item); } let prepared = await Promise.all( - [...deduped.values()].map(({ url, entry }) => - this.#prepareIndexRow(url, entry), + [...deduped.values()].map(({ url, entry, seq }) => + this.#prepareIndexRow(url, entry, seq), ), ); await this.#upsertIndexRows(prepared); } else { - for (let { url, entry } of buffered) { - await this.#writeEntryNow(url, entry); + for (let { url, entry, seq } of buffered) { + await this.#writeEntryNow(url, entry, seq); } } // Clear only after the rows have durably landed. If a write throws, the @@ -1063,7 +1103,11 @@ export class Batch { this.#invalidations.add(url.href); let start = Date.now(); try { - await this.#writeEntryNow(url, entry); + await this.#writeEntryNow( + url, + entry, + this.#positionOf(url, rowType(entry)), + ); } finally { this.#writeMs += Date.now() - start; } @@ -1099,10 +1143,18 @@ export class Batch { // between the two writes re-visits the URL rather than resuming a row whose // rendering never landed. (A split-mode batch writes no HTML — its spawned // `prerender_html` job owns that channel.) - async #writeEntryNow(url: URL, entry: SearchIndexEntry): Promise { - let { preparedEntry, htmlEntry } = await this.#prepareIndexRow(url, entry); + async #writeEntryNow( + url: URL, + entry: SearchIndexEntry, + seq: number, + ): Promise { + let { preparedEntry, htmlEntry } = await this.#prepareIndexRow( + url, + entry, + seq, + ); if (!this.#splitPrerenderHtml) { - await this.writePrerenderedHtmlRow(url, htmlEntry); + await this.writePrerenderedHtmlRow(url, htmlEntry, seq); } let { nameExpressions, valueExpressions } = asExpressions(preparedEntry, { jsonFields: this.#jsonColumnNames(), @@ -1191,6 +1243,34 @@ export class Batch { .map(([column]) => column); } + // The position `url`'s `type` row takes in this fan-out's write order: + // the next number the first time the pass writes that row, and the same + // number every time after. See `#writePositions`. + #positionOf(url: URL, type: BoxelIndexTable['type']): number { + let key = `${url.href}|${type}`; + let taken = this.#writePositions.get(key); + if (taken !== undefined) { + return taken; + } + let position = this.#writeSeq++; + this.#writePositions.set(key, position); + return position; + } + + // The write-side stamps every row this batch writes carries, on both + // channels: which pass wrote it, when, and where it sits in that pass's + // write order. `seq` comes from the caller rather than from `#writeSeq` + // here, so the two rows a fused visit produces — its `boxel_index` half + // and its `prerendered_html` half — share one position instead of + // consuming two. + #writeSideStamps(seq: number): Diagnostics { + return { + invalidationId: this.#currentInvalidationId, + indexedAt: Date.now(), + writeSeq: seq, + }; + } + // Build the sanitized `boxel_index_working` row payload — and the paired // `prerendered_html` entry the fused path writes — for an entry, without // performing the upsert. @@ -1199,20 +1279,21 @@ export class Batch { // from the Prerenderer's `response.meta` (already flattened in // `visit-file.ts`); the write-side `invalidationId` (minted once per Batch, // so every row from the same pass shares a queryable correlation key) and - // `indexedAt` are stamped now. The canonical storage is the `diagnostics` - // column; for error rows the blob is ALSO mirrored onto + // `indexedAt` are stamped now, alongside the `writeSeq` its caller assigned + // when the row entered the write path. The canonical storage is the + // `diagnostics` column; for error rows the blob is ALSO mirrored onto // `error_doc.diagnostics` so the UI read path keeps working unchanged. // jsonb-illegal bytes are stripped once, over the whole row, by the // `sanitizeForJsonb` at the end. async #prepareIndexRow( url: URL, entry: SearchIndexEntry, + writeSeq: number, ): Promise { let href = url.href; let diagnostics: Diagnostics = { ...(entry.diagnostics ?? {}), - invalidationId: this.#currentInvalidationId, - indexedAt: Date.now(), + ...this.#writeSideStamps(writeSeq), }; let errorEntry = isErrorEntry(entry) ? { @@ -1416,15 +1497,31 @@ export class Batch { `updatePrerenderedHtmlEntry is only valid on a prerenderHtmlOnly batch`, ); } - await this.writePrerenderedHtmlRow(url, entry); + // A prerenderHtmlOnly batch has no index half, so each rendering takes + // its own position in this job's write order. + await this.writePrerenderedHtmlRow( + url, + entry, + this.#positionOf(url, prerenderedRowType(entry)), + ); } // The prerendered_html row write shared by the two producers of renderings: // a `prerenderHtmlOnly` batch (via `updatePrerenderedHtmlEntry`) and a fused // batch (via `updateEntry`, which lands each visit's HTML half here inline). + // + // `seq` is this row's position in the batch's write order; the write-side + // stamps built from it are merged over the render's own diagnostics, so a + // rendering is groupable and orderable by the same two keys as an index + // row (`invalidationId` + `writeSeq`). A `prerenderHtmlOnly` batch mints + // its `invalidationId` in the constructor and never calls `invalidate()`, + // so the id groups that whole job — it is the render channel's own + // grouping key and does not equal the spawning index pass's id. Join the + // two channels on `url` (plus `generation`), not on `invalidationId`. private async writePrerenderedHtmlRow( url: URL, entry: PrerenderedHtmlEntry | PrerenderedHtmlErrorEntry, + seq: number, ): Promise { if (!new RealmPaths(this.realmURL, this.virtualNetwork).inRealm(url)) { return; @@ -1443,6 +1540,13 @@ export class Batch { ); } this.#invalidations.add(url.href); + // Every rendering carries the stamps, whether or not the render itself + // reported any diagnostics — an unstamped row could not be attributed to + // a pass at all, which is what the render channel lacked. + let diagnostics: Diagnostics = { + ...(entry.diagnostics ?? {}), + ...this.#writeSideStamps(seq), + }; let payload: Record; switch (entry.type) { case 'instance': @@ -1459,7 +1563,7 @@ export class Batch { deps, last_known_good_deps: deps, error_doc: null, - diagnostics: entry.diagnostics ?? null, + diagnostics, screenshots: entry.screenshots ?? null, }; break; @@ -1472,11 +1576,18 @@ export class Batch { type, ); // The column is the canonical home for the failing render's - // diagnostics; the copy on `error_doc.diagnostics` mirrors the - // `boxel_index` error-row pattern so error-doc consumers read one - // shape on both channels. Unlike the HTML columns below, the - // diagnostics are NOT taken from the last-known-good production - // row — they describe this failing render. + // diagnostics. The copy on `error_doc.diagnostics` is the read path + // operator mode surfaces ("send error to AI assistant" renders the + // blob verbatim), so it mirrors the entry's own diagnostics and adds + // nothing: this pass's stamps are bookkeeping for the operator + // queries rather than for that dialog. What the entry arrives with + // differs by pipeline, and the mirror follows it — a split + // pipeline's render entry carries render-produced fields only, while + // a fused visit's entry is built from its index half's blob + // (`prerenderedHtmlEntryFrom`) and so already has that row's stamps + // merged in. Unlike the HTML columns below, neither copy is taken + // from the last-known-good production row: both describe this + // failing render. let errorDoc = this.normalizeErrorDoc( { ...entry.error, @@ -1516,7 +1627,7 @@ export class Batch { ], last_known_good_deps: production?.last_known_good_deps ?? null, error_doc: errorDoc, - diagnostics: entry.diagnostics ?? null, + diagnostics, // Like the HTML columns above: the manifest is a last-known-good // artifact — its objects still exist in the MediaCache and the // preserved HTML may reference them by name. @@ -2059,6 +2170,10 @@ export class Batch { // = `) also surface the delete rows for this pass — otherwise // tombstones would inherit a stale ID from a prior write or stay // NULL entirely, misattributing deletes in the grouping view. + // No `writeSeq`: these land before the pass has visited anything, so + // ordering them against the visit rows that overwrite them would say + // nothing, and a URL the pass never visits (a deletion) is genuinely + // absent from the visit order. // // Filter out URLs the previous attempt of this job already wrote // a real (non-tombstone) row for. Tombstoning would upsert over @@ -2328,11 +2443,23 @@ export class Batch { ); } await this.ready; + // Drain anything still buffered under the OUTGOING correlation ID before + // rotating it. `#prepareIndexRow` reads the ID at flush time, so a row + // buffered before this call and flushed after it would be filed under the + // new fan-out while carrying the old one's write sequence — attributed to + // a change it had nothing to do with. A no-op on the production path, + // where `invalidate()` runs once per batch before any visit. + await this.flushWriteBuffer(); // Mint a fresh correlation ID for this invalidation fan-out; every // subsequent `updateEntry` on this batch stamps it into the row's // `diagnostics` so operators can group the rows touched by - // the same triggering change. + // the same triggering change. The write sequence restarts with it — and + // the positions rows have already taken are dropped — so `writeSeq` is + // 0-based within each `invalidationId` rather than within the batch's + // lifetime. this.#currentInvalidationId = uuidv4(); + this.#writeSeq = 0; + this.#writePositions.clear(); let start = Date.now(); this.#perfLog.debug( `${jobIdentity} starting invalidation of ${urls.map((u) => u.href).join()}`, @@ -2869,6 +2996,21 @@ function baseTypeFromError(entry: { // The `boxel_index` row type an entry lands under — the pkey is // (url, realm_url, type), so this keys the flush dedup that keeps a single // multi-row upsert from touching one conflict target twice. +// The `prerendered_html` row an entry writes to, error entries folded onto +// the row they preserve — the render channel's `rowType`. +function prerenderedRowType( + entry: PrerenderedHtmlEntry | PrerenderedHtmlErrorEntry, +): BoxelIndexTable['type'] { + switch (entry.type) { + case 'instance-error': + return 'instance'; + case 'file-error': + return 'file'; + default: + return entry.type; + } +} + function rowType(entry: SearchIndexEntry): BoxelIndexTable['type'] { return isErrorEntry(entry) ? baseTypeFromError(entry) : entry.type; } diff --git a/packages/runtime-common/index.ts b/packages/runtime-common/index.ts index 38d41f8fb4c..ba76af28aad 100644 --- a/packages/runtime-common/index.ts +++ b/packages/runtime-common/index.ts @@ -713,30 +713,82 @@ export interface IndexVisitClientTimings { // url). Named `Diagnostics` (not `TimingDiagnostics`) because the block is // not purely about timing: it also carries `brokenLinks`, the // broken-link findings the render surfaced. Extends -// `RenderTimeoutDiagnostics` (which already carries `requestId`) with two -// write-side stamps applied at `IndexWriter.updateEntry` time: +// `RenderTimeoutDiagnostics` (which already carries `requestId`) with three +// write-side stamps. Every live row either channel WRITES carries all three, +// stamped as the row enters the IndexWriter's write path — so a row is +// always attributable to the pass that wrote it, whether or not its render +// reported anything. The exception is a row a realm COPY produced +// (`Batch.copyFrom` / `copyPrerenderedHtmlFrom` clone the source realm's +// rows rather than rendering them): those keep whatever the source row +// carried, so they name the source realm's pass, or nothing at all if that +// row predates these stamps. The three stamps are: // -// - `invalidationId` — one UUID per `Batch`; every row touched by -// the same indexing pass (incremental fan-out or fromScratch) -// shares it, so operators can `SELECT ... WHERE -// diagnostics->>'invalidationId' = ''` and see the -// whole batch. +// - `invalidationId` — one UUID per invalidation fan-out: minted when the +// `Batch` is created, so a from-scratch pass (which never calls +// `invalidate()`) still has one, and refreshed at the top of each +// `invalidate()` call so the id names one triggering change rather than +// the batch's whole lifetime. An index pass invalidates once, so in +// practice the id covers the batch too, and operators can `SELECT ... +// WHERE diagnostics->>'invalidationId' = ''` to read back the whole +// fan-out. The `prerender_html` job an index pass spawns is its own +// batch with its own id: each groups its own channel's fan-out, so join +// the two channels on `url` (plus `generation`), never on this. // - `indexedAt` — wall-clock the write happened. +// - `writeSeq` — the row's position within that fan-out's write order. // -// All fields are optional because writers populate incrementally: -// render-side fields come from the Prerenderer's response meta, the -// write-side stamps come from the IndexWriter. Any stage may skip -// pieces that aren't applicable (e.g. non-timeout renders have no +// A tombstone takes no position in the write order, so `writeSeq` is absent +// on one. The index channel's tombstones do carry the other two: they are +// written by `invalidate()` under the id it just minted, and a visited URL's +// row then overwrites its tombstone. The render channel's tombstones clear +// `diagnostics` outright and so carry none of the three. +// +// Every other field is optional because writers populate incrementally: +// render-side fields come from the Prerenderer's response meta. Any stage +// may skip pieces that aren't applicable (e.g. non-timeout renders have no // `renderStage`, in-process callers have no `requestId`). // Extends both render-side diagnostic shapes so the persisted blob types // every field that actually lands in it: server-observed timings from // `RenderTimeoutDiagnostics` and the host-side `render.meta` block from // `PrerenderMetaDiagnostics` (computed-field counters plus `brokenLinks`). -// The two write-side stamps below are added at `IndexWriter.updateEntry`. export interface Diagnostics extends RenderTimeoutDiagnostics, PrerenderMetaDiagnostics { invalidationId?: string; indexedAt?: number; + // 0-based position of this row among the batch's row writes, stamped when + // the row enters the write path. `indexedAt` only resolves to the + // millisecond, and a batch's rows drain through buffered multi-row upserts + // that share one timestamp, so this is the only field that orders two rows + // written by the same batch. Grouped with `invalidationId`, it + // reconstructs the visit order of either channel. A card instance + // contributes two rows written back to back — its `file` row and its + // `instance` row — so reduce to one position per URL rather than selecting + // rows (a module, which has only a `file` row, is unaffected by the + // reduction): + // + // SELECT url, min((diagnostics->>'writeSeq')::int) AS seq + // FROM boxel_index + // WHERE diagnostics->>'invalidationId' = '' + // GROUP BY url + // ORDER BY seq + // + // An incremental index pass writes the URLs its triggering write named + // ahead of the dependents its fan-out discovered, so the targets hold the + // lowest sequences — with two qualifications, both from + // `prioritizeWrittenURLs`: a recorded dependency still puts a dependency + // ahead of the URL that depends on it, and modules are written before + // instances whether or not the write named them. + // + // Sequences are per batch, and a fused visit's two rows share one — its + // `boxel_index` half and its `prerendered_html` half describe one position, + // not two. A split pipeline's channels number independently, so a + // sequence is only comparable within one `invalidationId`. + // + // A row written more than once in a pass keeps the position of its first + // write, so a sequence marks where the pass's work on that row began and a + // fan-out's positions stay gapless. + // + // Absent on a tombstoned row and on rows written before the stamp existed. + writeSeq?: number; // Host-shell token the prerender server had been told was current when this // render started, and again when its response was assembled. Two different // values mean the render straddled a host redeploy: the page resolved