You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
The first `|`-section is the **sequential wall-clock timeline** (these sum to ≈ `handler`). The `busyMs(parallel-sum)` section is the inner per-result work that runs **concurrently** inside `loadLinks`'s `Promise.all`, so it is summed across N parallel ops and is **NOT wall-clock** — `populate` can read as millions of ms on a large result set. Read it as a **ratio** (which sub-step dominates within `loadLinks`) or divide by `results` for a per-item average; never add it to the timeline.
820
+
The `|`-section is the **sequential wall-clock timeline** (these sum to ≈ `handler`).
821
+
822
+
**Note — a prerender search skips `loadLinks`.** These lines emit only for prerender `_federated-search` (the correlation id is prerender-gated), and a prerender search skips the relationship-assembly pass: the host re-resolves every result from card+source and reads only `data[].id`, so the realm-server returns each result's pristine row (id + attributes + any static-link relationships) + page meta and does not run `populateQueryFields`. The line therefore carries **no `loadLinks` stage and no `busyMs(parallel-sum)` section** (no `populate` / `cacheRead` / `cacheWrite` / `cacheHit` / `cacheMiss`) — those are the per-result umbrella assembly + per-instance wire-format cache, which do not run on this path. The dominant cost on a prerender search is `sql` (or `stringify` for a fat result set, or queue-wait — see branch 4).
-`sql` — the `IndexQueryEngine.searchCards` query (the actual SQL).
827
-
-`loadLinks` — the post-SQL relationship-assembly pass over the whole result set (the wall-clock of the parallel `populate`/cache work below).
828
-
-`stringify` — `JSON.stringify` of the response wire-format.
829
-
-`coalescedWait` — this request coalesced onto an already-in-flight identical search (CS-11121 dedup) and waited for it; the real sql/loadLinks work is on the **leader's** line, not this one.
828
+
-`sql` — the `IndexQueryEngine.searchCards` query (the actual SQL). For a prerender search this is essentially the whole `handler`.
829
+
-`stringify` — `JSON.stringify` of the response wire-format (for a prerender search, the pristine result rows + page meta, with no query-field umbrellas or `included[]`).
830
+
-`coalescedWait` — this request coalesced onto an already-in-flight identical search (in-flight dedup) and waited for it; the real sql work is on the **leader's** line, not this one.
830
831
-`handler=` — handler entry → response assembled (≈ the sum of the wall-clock stages).
831
832
832
-
Busy-time (parallel-sum, NOT wall-clock):
833
-
834
-
-`populate` — the per-instance query-field assembly (definition lookup + field-tree walk), summed across all results.
835
-
-`cacheRead` / `cacheWrite` (+ `cacheHit` / `cacheMiss` counters) — the per-instance wire-format cache (`job_scoped_instance_cache`) round-trips, summed across all results.
836
-
837
833
**Reading it — the decision tree.**
838
834
839
-
1.**`sql=` is the bulk of `handler`** → a genuinely slow query. Rare here (the premise is fast SQL); confirm with `pg_stat_activity` / `EXPLAIN`. Fast SQL but large `sql=` means lock / connection-pool wait inside the query call.
840
-
2.**`loadLinks` dominates `handler`** → the post-SQL relationship/query-field assembly is the cost (the per-instance wire-format work). Use the `busyMs(parallel-sum)` ratio to see what _inside_ loadLinks dominates: `populate ≫ cacheRead/cacheWrite` means it's the CPU field-walk, not the cache DB round-trips. Check `cacheHit` / `cacheMiss`: a low hit rate means the instance cache isn't helping (e.g. unique-per-card queries) so every result is assembled from scratch.
841
-
3.**`stringify` dominates** → serializing a large federated response. Look at `results=` for a fat result set.
842
-
4.**`dur` (realm:requests) ≫ `handler` (realm:search-timing)** → the time is NOT inside the handler. It was spent **queued before the handler ran** (or sending). This is the saturation fingerprint: cross-reference `realm:health` near the same timestamp — if `eventLoopLagMs` spiked into the hundreds/thousands with `inFlightSearch` high, the single-threaded realm-server's event loop was starved (synchronous post-SQL serialization across many concurrent searches), so the request sat unserviced even though, once it ran, the handler was fast. That is the CS-10820 saturation class seen from the server side.
843
-
5.**`coalescedWait` dominates** → this follower waited on another in-flight identical search. Find the leader (same job + query, overlapping time); its line carries the real breakdown.
835
+
1.**`sql=` is the bulk of `handler`** → a genuinely slow query. Confirm with `pg_stat_activity` / `EXPLAIN`. Fast SQL but large `sql=` means lock / connection-pool wait inside the query call. (For a prerender search this is the typical shape — the post-SQL assembly doesn't run on that path, so `sql` carries most of the handler.)
836
+
2.**`stringify` dominates** → serializing a large federated response. Look at `results=` for a fat result set.
837
+
3.**`dur` (realm:requests) ≫ `handler` (realm:search-timing)** → the time is NOT inside the handler. It was spent **queued before the handler ran** (or sending). This is the saturation fingerprint: cross-reference `realm:health` near the same timestamp — if `eventLoopLagMs` spiked into the hundreds/thousands with `inFlightSearch` high, the single-threaded realm-server's event loop was starved, so the request sat unserviced even though, once it ran, the handler was fast. That is the CS-10820 saturation class seen from the server side.
838
+
4.**`coalescedWait` dominates** → this follower waited on another in-flight identical search. Find the leader (same job + query, overlapping time); its line carries the real breakdown.
844
839
845
840
**Getting the logs.** These emit from the **realm-server** process (`handle-search` → `searchRealms`). Reach them with the `tail-logs` skill (Loki, realm-server family) or, for staging/prod CloudWatch, the `aws-access` skill:
0 commit comments