Search-doc diagnostics: per-field evaluation and per-link-load timings

packages/base/searchable.ts

@@ -6,6 +6,7 @@ import {
   primitive,
   relativeTo,
   routesForField,
+  type SearchDocTimings,
   type SerializedError,
 } from '@cardstack/runtime-common';
 import {
@@ -56,6 +57,12 @@ export async function searchDocFromFields(
   // owner — whether or not the render happened to load it (a `{ id }`-only link
   // contributes none, since its target's data is not in the doc).
   dependencies: Set<string> = new Set(),
+  // Optional timing collector, filled in place as the walk runs (so entries
+  // recorded before a mid-walk throw survive): per-field inclusive
+  // evaluation wall-clock keyed by dotted path, and one entry per link-
+  // target load performed. Each sub-collector is opt-in and raw — the
+  // caller bounds and rounds before persisting.
+  timings?: SearchDocTimings,
 ): Promise<Record<string, any>> {
   let routes = seedSearchableRoutes(
     instance.constructor as unknown as typeof BaseDef,
@@ -67,6 +74,8 @@ export async function searchDocFromFields(
     [],
     getStore(instance),
     dependencies,
+    '',
+    timings,
   )) as Record<string, any>;
 }
 
@@ -167,6 +176,10 @@ async function searchableQueryableValue(
   // must still load against the owner's store.
   store: CardStore,
   dependencies: Set<string>,
+  // Dotted field path from the indexed card's root down to `value` ('' at
+  // the root); keys the `timings` entries.
+  path: string,
+  timings: SearchDocTimings | undefined,
 ): Promise<any> {
   if (primitive in fieldCard) {
     // Delegate to the field's own queryableValue. The default handles
@@ -216,6 +229,13 @@ async function searchableQueryableValue(
     let isDeclaredLink =
       (field!.fieldType === 'linksTo' || field!.fieldType === 'linksToMany') &&
       !field!.computeVia;
+    let fieldPath = path === '' ? fieldName : `${path}.${fieldName}`;
+    // Inclusive per-field timing: starts before the field read — a
+    // computed's computeVia runs inside peekAtField — and covers the nested
+    // recursion and link loads below, so a slow leaf surfaces together with
+    // every ancestor on its path. Guarded on the collector so an
+    // uninstrumented walk pays no timer calls.
+    let fieldStart = timings?.fieldsMs ? performance.now() : 0;
     let rawValue =
       isDeclaredLink && !getDataBucket(value).has(fieldName)
         ? null
@@ -231,6 +251,8 @@ async function searchableQueryableValue(
             nextStack,
             store,
             dependencies,
+            fieldPath,
+            timings,
           ),
         ]);
         break;
@@ -255,6 +277,8 @@ async function searchableQueryableValue(
             nextStack,
             store,
             dependencies,
+            fieldPath,
+            timings,
           );
           if (v != null) {
             items.push(v);
@@ -276,6 +300,8 @@ async function searchableQueryableValue(
             store,
             makeAbsoluteURL,
             dependencies,
+            fieldPath,
+            timings,
           ),
         ]);
         break;
@@ -292,11 +318,19 @@ async function searchableQueryableValue(
             store,
             makeAbsoluteURL,
             dependencies,
+            fieldPath,
+            timings,
           ),
         ]);
         break;
       }
     }
+    if (timings?.fieldsMs) {
+      // Accumulate rather than assign: a plural field's items (and a card
+      // re-entered on another branch) all land under one path key.
+      timings.fieldsMs[fieldPath] =
+        (timings.fieldsMs[fieldPath] ?? 0) + (performance.now() - fieldStart);
+    }
   }
   return Object.fromEntries(entries);
 }
@@ -314,6 +348,8 @@ async function searchableLink(
   store: CardStore,
   makeAbsoluteURL: (reference: string) => string,
   dependencies: Set<string>,
+  path: string,
+  timings: SearchDocTimings | undefined,
 ): Promise<any> {
   if (rawValue == null) {
     return null;
@@ -347,7 +383,13 @@ async function searchableLink(
     // getter. The store can't `toURL` a relative string, which would otherwise
     // degrade an expandable searchable link to `{ id }`.
     let resolvedRef = makeAbsoluteURL(rawValue.reference);
+    let loadStart = timings?.linkLoads ? performance.now() : 0;
     let result = await loadSearchableTarget(store, resolvedRef);
+    timings?.linkLoads?.push({
+      path,
+      target: resolvedRef,
+      ms: performance.now() - loadStart,
+    });
     if (result.status === 'broken') {
       // Plant the terminal sentinel on the owner's field so `getBrokenLinks`
       // (which reads terminal sentinels from the data bucket) records this
@@ -374,6 +416,8 @@ async function searchableLink(
     stack,
     store,
     dependencies,
+    path,
+    timings,
   );
 }
 
@@ -390,6 +434,8 @@ async function searchableLinksToMany(
   store: CardStore,
   makeAbsoluteURL: (reference: string) => string,
   dependencies: Set<string>,
+  path: string,
+  timings: SearchDocTimings | undefined,
 ): Promise<any[] | null> {
   // A whole-field sentinel (errored/unresolved plural) is not iterable; treat
   // as empty, same as `LinksToMany.queryableValue`.
@@ -423,7 +469,13 @@ async function searchableLinksToMany(
     if (isNotLoadedValue(item)) {
       // Resolve a relative reference before the load — see `searchableLink`.
       let resolvedRef = makeAbsoluteURL(item.reference);
+      let loadStart = timings?.linkLoads ? performance.now() : 0;
       let result = await loadSearchableTarget(store, resolvedRef);
+      timings?.linkLoads?.push({
+        path,
+        target: resolvedRef,
+        ms: performance.now() - loadStart,
+      });
       if (result.status === 'broken') {
         // Plant the sentinel into the failed slot so `getBrokenLinks` records
         // this broken searchable element (see `searchableLink`). Assign through
@@ -449,6 +501,8 @@ async function searchableLinksToMany(
       stack,
       store,
       dependencies,
+      path,
+      timings,
     );
     if (expanded != null) {
       out.push(

packages/host/app/routes/render/meta.ts

@@ -15,6 +15,8 @@ import {
   relationshipEntries,
   realmURL,
   snapshotRuntimeDependencies,
+  type SearchDocLinkLoad,
+  type SearchDocTimings,
   type SingleCardDocument,
   type PrerenderMeta,
   type PrerenderMetaDiagnostics,
@@ -46,6 +48,77 @@ const computePerfLog = logger('host:computed-perf');
 const SEARCHABLE_SETTLE_MAX_PASSES = 20;
 const SEARCHABLE_SETTLE_REQUIRED_STABLE_PASSES = 2;
 
+// Persistence bounds for the per-field / per-link-load search-doc timings.
+// The raw collectors are unbounded; only the slowest entries at/over the
+// floor land on the row, so a typical ~1 ms search doc records nothing and
+// a wide card can't bloat its diagnostics blob.
+const SEARCH_DOC_TIMING_FLOOR_MS = 1;
+const SEARCH_DOC_TIMING_MAX_ENTRIES = 20;
+
+const roundMs = (ms: number) => Math.round(ms * 100) / 100;
+
+// Slowest-N-at/over-the-floor pruning for the per-field timings. Rank by
+// value when reading — jsonb normalizes key order, so the persisted object
+// carries no ordering. An ancestor's inclusive time is >= any descendant's,
+// so a kept entry's parent chain makes the cut with it (barring an
+// exact-tie at the cut-off).
+function pruneSearchDocFieldsMs(
+  fieldsMs: Record<string, number>,
+): Record<string, number> | undefined {
+  let kept = Object.entries(fieldsMs)
+    .filter(([, ms]) => ms >= SEARCH_DOC_TIMING_FLOOR_MS)
+    .sort(([, a], [, b]) => b - a)
+    .slice(0, SEARCH_DOC_TIMING_MAX_ENTRIES);
+  return kept.length > 0
+    ? Object.fromEntries(kept.map(([path, ms]) => [path, roundMs(ms)]))
+    : undefined;
+}
+
+// Same pruning for link-target loads. The floor also drops the near-zero
+// entries recorded when a target was already resident in the store, so what
+// survives is the loads that actually cost something.
+function pruneSearchDocLinkLoads(
+  linkLoads: SearchDocLinkLoad[],
+): SearchDocLinkLoad[] | undefined {
+  let kept = linkLoads
+    .filter(({ ms }) => ms >= SEARCH_DOC_TIMING_FLOOR_MS)
+    .sort((a, b) => b.ms - a.ms)
+    .slice(0, SEARCH_DOC_TIMING_MAX_ENTRIES)
+    .map((load) => ({ ...load, ms: roundMs(load.ms) }));
+  return kept.length > 0 ? kept : undefined;
+}
+
+// Multiset diff over the store's bounded completed-load histories: the
+// entries present in `after` beyond their multiplicity in `before`. Used to
+// attribute loads the settle loop fired through field getters (a computed
+// reading a link loads via `lazilyLoadLink`, not via the generator's
+// targeted loading) — those loads land in the store's history but never
+// pass through the generator's collector. The histories keep only the
+// slowest entries, so a load evicted by slower siblings goes unreported;
+// what survives is by construction the part worth attributing. Exported for
+// unit testing.
+export function newLoadEntries(
+  before: Array<{ url: string; ms: number }>,
+  after: Array<{ url: string; ms: number }>,
+): Array<{ url: string; ms: number }> {
+  let seen = new Map<string, number>();
+  for (let { url, ms } of before) {
+    let key = `${url}|${ms}`;
+    seen.set(key, (seen.get(key) ?? 0) + 1);
+  }
+  let fresh: Array<{ url: string; ms: number }> = [];
+  for (let entry of after) {
+    let key = `${entry.url}|${entry.ms}`;
+    let count = seen.get(key) ?? 0;
+    if (count > 0) {
+      seen.set(key, count - 1);
+    } else {
+      fresh.push(entry);
+    }
+  }
+  return fresh;
+}
+
 // The base module whose generator produces every search doc. Recorded as a
 // dependency of the meta output directly (see the deps union below) rather
 // than relying on its per-loader-cached module-load hook to fire during a
@@ -99,7 +172,34 @@ export default class RenderMetaRoute extends Route<Model> {
     // visit, or an HTML render sharing this tab), the first pass finds every
     // target resident and `store.loaded()` resolves immediately — there is
     // nothing left to wait for.
-    await this.#settleSearchableLoads(instance, searchable);
+    //
+    // Link-load cost lives HERE: the settle passes perform the actual
+    // target loads (each load registers its instance in the store, so the
+    // timed generation below finds everything resident). The collector
+    // gathers one entry per performed load across all passes — a target
+    // loads on the first pass that reaches it and is a resident hit
+    // afterward — for the `searchDocLinkLoads` diagnostic. Loads the passes
+    // fire indirectly through field getters (a computed reading a link)
+    // bypass the generator's collector, so the store's completed-load
+    // histories are snapshotted around the loop and their delta is folded
+    // in — with an empty `path`, since the store can't name the owning
+    // field.
+    let recentLoadsBefore = [
+      ...this.store.recentCardDocLoads(),
+      ...this.store.recentFileMetaLoads(),
+    ];
+    let settleLinkLoads: SearchDocLinkLoad[] = [];
+    let settleStart = performance.now();
+    let settlePasses = await this.#settleSearchableLoads(
+      instance,
+      searchable,
+      settleLinkLoads,
+    );
+    let searchDocSettleMs = performance.now() - settleStart;
+    let getterFiredLoads = newLoadEntries(recentLoadsBefore, [
+      ...this.store.recentCardDocLoads(),
+      ...this.store.recentFileMetaLoads(),
+    ]).map(({ url, ms }) => ({ path: '', target: url, ms }));
 
     // Union the render route's captured deps with a fresh snapshot: the
     // settle loop above loaded links through the tracked getter (each a
@@ -193,9 +293,15 @@ export default class RenderMetaRoute extends Route<Model> {
     // not itself load that target.
     let searchDocStart = performance.now();
     let searchableDeps = new Set<string>();
+    // Per-field evaluation timings come from this timed walk (link loads
+    // settled above, so it measures evaluation, not loading); any load the
+    // walk still performs — a settle that hit its pass cap, a race — joins
+    // the settle passes' entries.
+    let searchDocTimings: SearchDocTimings = { fieldsMs: {}, linkLoads: [] };
     let searchDoc: Record<string, any> = await searchable.searchDocFromFields(
       instance,
       searchableDeps,
+      searchDocTimings,
     );
     let searchDocMs = performance.now() - searchDocStart;
     if (searchableDeps.size > 0) {
@@ -216,15 +322,34 @@ export default class RenderMetaRoute extends Route<Model> {
     // `cardTitle` computed already present in the search doc.
     searchDoc._title = searchDoc.cardTitle;
 
+    let searchDocFieldsMs = pruneSearchDocFieldsMs(
+      searchDocTimings.fieldsMs ?? {},
+    );
+    // A target the generator loaded directly also lands in the store's
+    // history; keep the generator's entry (it carries the field path) and
+    // drop the store's duplicate.
+    let targetedLoads = [
+      ...settleLinkLoads,
+      ...(searchDocTimings.linkLoads ?? []),
+    ];
+    let targetedUrls = new Set(targetedLoads.map(({ target }) => target));
+    let searchDocLinkLoads = pruneSearchDocLinkLoads([
+      ...targetedLoads,
+      ...getterFiredLoads.filter(({ target }) => !targetedUrls.has(target)),
+    ]);
     let diagnostics: PrerenderMetaDiagnostics = {
       ...(passSnapshot
         ? {
             computedCalls: passSnapshot.calls,
             computedCacheHits: passSnapshot.cacheHits,
           }
         : {}),
-      serializeMs: Math.round(serializeMs * 100) / 100,
-      searchDocMs: Math.round(searchDocMs * 100) / 100,
+      serializeMs: roundMs(serializeMs),
+      searchDocMs: roundMs(searchDocMs),
+      searchDocSettleMs: roundMs(searchDocSettleMs),
+      searchDocSettlePasses: settlePasses,
+      ...(searchDocFieldsMs ? { searchDocFieldsMs } : {}),
+      ...(searchDocLinkLoads ? { searchDocLinkLoads } : {}),
     };
 
     // Record broken `linksTo` / `linksToMany` targets as searchable
@@ -249,7 +374,7 @@ export default class RenderMetaRoute extends Route<Model> {
       }
     }
     computePerfLog.debug(
-      `render.meta computed counts cardId=${instance.id} calls=${diagnostics.computedCalls ?? 'n/a'} cacheHits=${diagnostics.computedCacheHits ?? 'n/a'} serializeMs=${diagnostics.serializeMs} searchDocMs=${diagnostics.searchDocMs}`,
+      `render.meta computed counts cardId=${instance.id} calls=${diagnostics.computedCalls ?? 'n/a'} cacheHits=${diagnostics.computedCacheHits ?? 'n/a'} serializeMs=${diagnostics.serializeMs} searchDocMs=${diagnostics.searchDocMs} searchDocSettleMs=${diagnostics.searchDocSettleMs} searchDocSettlePasses=${diagnostics.searchDocSettlePasses}`,
     );
 
     return {
@@ -273,12 +398,19 @@ export default class RenderMetaRoute extends Route<Model> {
   // discarded (a throwaway dependency set); the authoritative generation runs
   // afterward against the settled store. See the call site for why this is
   // needed and how it composes with the /render template settle.
+  //
+  // Returns the number of passes run. Each performed link-target load is
+  // recorded into `linkLoads` (the collector fills incrementally, so loads
+  // recorded before a swallowed mid-walk throw survive); a searchable build
+  // that predates the collector parameter simply leaves it empty.
   async #settleSearchableLoads(
     instance: CardDef,
     searchable: Awaited<ReturnType<CardService['getSearchable']>>,
-  ): Promise<void> {
+    linkLoads: SearchDocLinkLoad[],
+  ): Promise<number> {
     let observedGeneration = this.store.loadGeneration;
     let stablePasses = 0;
+    let timings: SearchDocTimings = { linkLoads };
     for (let pass = 0; pass < SEARCHABLE_SETTLE_MAX_PASSES; pass++) {
       // A computed that reads a not-yet-loaded link (e.g.
       // `this.author.firstName`) throws on the first pass — the getter fires
@@ -288,15 +420,15 @@ export default class RenderMetaRoute extends Route<Model> {
       // target. A genuine (non-load-race) failure resurfaces in the
       // authoritative generation the caller runs after this settles.
       try {
-        await searchable.searchDocFromFields(instance);
+        await searchable.searchDocFromFields(instance, undefined, timings);
       } catch {
         // intentionally ignored during settle — see above
       }
       await this.store.loaded();
       let nextGeneration = this.store.loadGeneration;
       if (nextGeneration === observedGeneration) {
         if (++stablePasses >= SEARCHABLE_SETTLE_REQUIRED_STABLE_PASSES) {
-          return;
+          return pass + 1;
         }
       } else {
         observedGeneration = nextGeneration;
@@ -306,6 +438,7 @@ export default class RenderMetaRoute extends Route<Model> {
     computePerfLog.warn(
       `render.meta searchable settle for ${instance.id} did not reach a stable load generation within ${SEARCHABLE_SETTLE_MAX_PASSES} passes; proceeding with the current store state`,
     );
+    return SEARCHABLE_SETTLE_MAX_PASSES;
   }
 }