Merge pull request #2019 from cardstack/debug-perf-logging

Optimize logic around invalidation

packages/host/app/components/card-prerender.gts

@@ -52,9 +52,15 @@ export default class CardPrerender extends Component {
     }
   }
 
-  private async fromScratch(realmURL: URL): Promise<IndexResults> {
+  private async fromScratch(
+    realmURL: URL,
+    invalidateEntireRealm: boolean,
+  ): Promise<IndexResults> {
     try {
-      let results = await this.doFromScratch.perform(realmURL);
+      let results = await this.doFromScratch.perform(
+        realmURL,
+        invalidateEntireRealm,
+      );
       return results;
     } catch (e: any) {
       if (!didCancel(e)) {
@@ -99,21 +105,26 @@ export default class CardPrerender extends Component {
     await register(this.fromScratch.bind(this), this.incremental.bind(this));
   });
 
-  private doFromScratch = enqueueTask(async (realmURL: URL) => {
-    let { reader, indexWriter } = this.getRunnerParams(realmURL);
-    let currentRun = new CurrentRun({
-      realmURL,
-      reader,
-      indexWriter,
-      renderCard: this.renderService.renderCard,
-      render: this.renderService.render,
-    });
-    setOwner(currentRun, getOwner(this)!);
+  private doFromScratch = enqueueTask(
+    async (realmURL: URL, invalidateEntireRealm: boolean) => {
+      let { reader, indexWriter } = this.getRunnerParams(realmURL);
+      let currentRun = new CurrentRun({
+        realmURL,
+        reader,
+        indexWriter,
+        renderCard: this.renderService.renderCard,
+        render: this.renderService.render,
+      });
+      setOwner(currentRun, getOwner(this)!);
 
-    let current = await CurrentRun.fromScratch(currentRun);
-    this.renderService.indexRunDeferred?.fulfill();
-    return current;
-  });
+      let current = await CurrentRun.fromScratch(
+        currentRun,
+        invalidateEntireRealm,
+      );
+      this.renderService.indexRunDeferred?.fulfill();
+      return current;
+    },
+  );
 
   private doIncremental = enqueueTask(
     async (

packages/host/app/lib/current-run.ts

@@ -59,6 +59,7 @@ import type LoaderService from '../services/loader-service';
 import type NetworkService from '../services/network';
 
 const log = logger('current-run');
+const perfLog = logger('index-perf');
 
 interface CardType {
   refURL: string;
@@ -121,24 +122,69 @@ export class CurrentRun {
     this.#render = render;
   }
 
-  static async fromScratch(current: CurrentRun): Promise<IndexResults> {
+  static async fromScratch(
+    current: CurrentRun,
+    invalidateEntireRealm?: boolean,
+  ): Promise<IndexResults> {
     let start = Date.now();
     log.debug(`starting from scratch indexing`);
+    perfLog.debug(
+      `starting from scratch indexing for realm ${current.realmURL.href}`,
+    );
 
     current.#batch = await current.#indexWriter.createBatch(current.realmURL);
-    let mtimes = await current.batch.getModifiedTimes();
-    await current.discoverInvalidations(current.realmURL, mtimes);
-    let invalidations = current.batch.invalidations.map(
-      (href) => new URL(href),
-    );
+    let invalidations: URL[] = [];
+    if (invalidateEntireRealm) {
+      perfLog.debug(
+        `flag was set to invalidate entire realm ${current.realmURL.href}, skipping invalidation discovery`,
+      );
+      let mtimesStart = Date.now();
+      let filesystemMtimes = await current.#reader.mtimes();
+      perfLog.debug(
+        `time to get file system mtimes ${Date.now() - mtimesStart} ms`,
+      );
+      invalidations = Object.keys(filesystemMtimes)
+        .filter(
+          (url) =>
+            // Only allow json and executable files to be invalidated so that we
+            // don't end up with invalidated files that weren't meant to be indexed
+            // (images, etc)
+            url.endsWith('.json') || hasExecutableExtension(url),
+        )
+        .map((url) => new URL(url));
+    } else {
+      let mtimesStart = Date.now();
+      let mtimes = await current.batch.getModifiedTimes();
+      perfLog.debug(
+        `completed getting index mtimes in ${Date.now() - mtimesStart} ms`,
+      );
+      let invalidateStart = Date.now();
+      invalidations = (
+        await current.discoverInvalidations(current.realmURL, mtimes)
+      ).map((href) => new URL(href));
+      perfLog.debug(
+        `completed invalidations in ${Date.now() - invalidateStart} ms`,
+      );
+    }
 
     await current.whileIndexing(async () => {
+      let visitStart = Date.now();
       for (let invalidation of invalidations) {
         await current.tryToVisit(invalidation);
       }
+      perfLog.debug(`completed index visit in ${Date.now() - visitStart} ms`);
+      let finalizeStart = Date.now();
       let { totalIndexEntries } = await current.batch.done();
+      perfLog.debug(
+        `completed index finalization in ${Date.now() - finalizeStart} ms`,
+      );
       current.stats.totalIndexEntries = totalIndexEntries;
       log.debug(`completed from scratch indexing in ${Date.now() - start}ms`);
+      perfLog.debug(
+        `completed from scratch indexing for realm ${
+          current.realmURL.href
+        } in ${Date.now() - start} ms`,
+      );
     });
     return {
       invalidations: [...(invalidations ?? [])].map((url) => url.href),
@@ -235,17 +281,26 @@ export class CurrentRun {
   private async discoverInvalidations(
     url: URL,
     indexMtimes: LastModifiedTimes,
-  ): Promise<void> {
+  ): Promise<string[]> {
     log.debug(`discovering invalidations in dir ${url.href}`);
+    perfLog.debug(`discovering invalidations in dir ${url.href}`);
+    let ignoreStart = Date.now();
     let ignorePatterns = await this.#reader.readFile(
       new URL('.gitignore', url),
     );
+    perfLog.debug(`time to get ignore rules ${Date.now() - ignoreStart} ms`);
     if (ignorePatterns && ignorePatterns.content) {
       this.ignoreMap.set(url.href, ignore().add(ignorePatterns.content));
       this.#ignoreData[url.href] = ignorePatterns.content;
     }
 
+    let mtimesStart = Date.now();
     let filesystemMtimes = await this.#reader.mtimes();
+    perfLog.debug(
+      `time to get file system mtimes ${Date.now() - mtimesStart} ms`,
+    );
+    let invalidationList: string[] = [];
+    let skipList: string[] = [];
     for (let [url, lastModified] of Object.entries(filesystemMtimes)) {
       if (!url.endsWith('.json') && !hasExecutableExtension(url)) {
         // Only allow json and executable files to be invalidated so that we
@@ -261,9 +316,25 @@ export class CurrentRun {
         indexEntry.lastModified == null ||
         lastModified !== indexEntry.lastModified
       ) {
-        await this.batch.invalidate(new URL(url));
+        invalidationList.push(url);
+      } else {
+        skipList.push(url);
       }
     }
+    if (skipList.length === 0) {
+      // the whole realm needs to be visited, no need to calculate
+      // invalidations--it's everything
+      return invalidationList;
+    }
+
+    let invalidationStart = Date.now();
+    for (let invalidationURL of invalidationList) {
+      await this.batch.invalidate(new URL(invalidationURL));
+    }
+    perfLog.debug(
+      `time to invalidate ${url} ${Date.now() - invalidationStart} ms`,
+    );
+    return this.batch.invalidations;
   }
 
   private async visitFile(

packages/host/app/services/local-indexer.ts

@@ -8,7 +8,10 @@ import { type TestRealmAdapter } from '@cardstack/host/tests/helpers/adapter';
 // for the test-realm-adapter
 export default class LocalIndexer extends Service {
   setup(
-    _fromScratch: (realmURL: URL) => Promise<IndexResults>,
+    _fromScratch: (
+      realmURL: URL,
+      invalidateEntireRealm: boolean,
+    ) => Promise<IndexResults>,
     _incremental: (
       url: URL,
       realmURL: URL,

packages/realm-server/handlers/handle-create-realm.ts

@@ -104,7 +104,7 @@ export default function handleCreateRealmRequest({
       }
 
       let creationTimeMs = Date.now() - start;
-      if (creationTimeMs > 15_000) {
+      if (creationTimeMs > 30_000) {
         let msg = `it took a long time, ${creationTimeMs} ms, to create realm for ${ownerUserId}, ${JSON.stringify(
           json.data.attributes,
         )}`;

packages/realm-server/server.ts

@@ -347,18 +347,21 @@ export class RealmServer {
       this.log.debug(`seed files for new realm ${url} copied to ${realmPath}`);
     }
 
-    let realm = new Realm({
-      url,
-      adapter,
-      secretSeed: this.secretSeed,
-      virtualNetwork: this.virtualNetwork,
-      dbAdapter: this.dbAdapter,
-      queue: this.queue,
-      matrix: {
-        url: this.matrixClient.matrixURL,
-        username,
+    let realm = new Realm(
+      {
+        url,
+        adapter,
+        secretSeed: this.secretSeed,
+        virtualNetwork: this.virtualNetwork,
+        dbAdapter: this.dbAdapter,
+        queue: this.queue,
+        matrix: {
+          url: this.matrixClient.matrixURL,
+          username,
+        },
       },
-    });
+      { invalidateEntireRealm: true },
+    );
     this.realms.push(realm);
     this.virtualNetwork.mount(realm.handle);
     return realm;

packages/runtime-common/index-writer.ts

@@ -7,6 +7,7 @@ import {
   trimExecutableExtension,
   RealmPaths,
   unixTime,
+  logger,
 } from './index';
 import { transpileJS } from './transpile';
 import {
@@ -97,6 +98,7 @@ export class Batch {
   readonly ready: Promise<void>;
   #invalidations = new Set<string>();
   #dbAdapter: DBAdapter;
+  #perfLog = logger('index-perf');
   private declare realmVersion: number;
 
   constructor(
@@ -464,6 +466,7 @@ export class Batch {
   ): Promise<
     { url: string; alias: string; type: 'instance' | 'module' | 'error' }[]
   > {
+    let start = Date.now();
     const pageSize = 1000;
     let results: (Pick<BoxelIndexTable, 'url' | 'file_alias'> & {
       type: 'instance' | 'module' | 'error';
@@ -495,6 +498,9 @@ export class Batch {
           // css is a subset of modules, so there won't by any references that
           // are css entries that aren't already represented by a module entry
           [`i.type != 'css'`],
+          // probably need to reevaluate this condition when we get to cross
+          // realm invalidation
+          [`i.realm_url =`, param(this.realmURL.href)],
         ]),
         'ORDER BY i.url COLLATE "POSIX"',
         `LIMIT ${pageSize} OFFSET ${pageNumber * pageSize}`,
@@ -504,6 +510,11 @@ export class Batch {
       results = [...results, ...rows];
       pageNumber++;
     } while (rows.length === pageSize);
+    this.#perfLog.debug(
+      `time to determine items that reference ${resolvedPath} ${
+        Date.now() - start
+      } ms`,
+    );
     return results.map(({ url, file_alias, type }) => ({
       url,
       alias: file_alias,
@@ -522,17 +533,11 @@ export class Batch {
       return [];
     }
     visited.add(resolvedPath);
-    let childInvalidations = await this.itemsThatReference(resolvedPath);
-    let realmPath = new RealmPaths(this.realmURL);
-    let invalidationsInThisRealm = childInvalidations.filter((c) =>
-      realmPath.inRealm(new URL(c.url)),
-    );
-
-    let invalidations = invalidationsInThisRealm.map(({ url }) => url);
-    let aliases = invalidationsInThisRealm.map(
-      ({ alias: moduleAlias, type, url }) =>
-        // for instances we expect that the deps for an entry always includes .json extension
-        type === 'instance' ? url : moduleAlias,
+    let items = await this.itemsThatReference(resolvedPath);
+    let invalidations = items.map(({ url }) => url);
+    let aliases = items.map(({ alias: moduleAlias, type, url }) =>
+      // for instances we expect that the deps for an entry always includes .json extension
+      type === 'instance' ? url : moduleAlias,
     );
     let results = [
       ...invalidations,

packages/runtime-common/realm-index-updater.ts

@@ -7,7 +7,7 @@ import {
   type Stats,
   type DBAdapter,
   type QueuePublisher,
-  type WorkerArgs,
+  type FromScratchArgs,
   type FromScratchResult,
   type IncrementalArgs,
   type IncrementalResult,
@@ -81,8 +81,8 @@ export class RealmIndexUpdater {
     return await this.#indexWriter.isNewIndex(this.realmURL);
   }
 
-  async run() {
-    await this.fullIndex();
+  async run(invalidateEntireRealm?: boolean) {
+    await this.fullIndex(invalidateEntireRealm);
   }
 
   indexing() {
@@ -92,12 +92,13 @@ export class RealmIndexUpdater {
   // TODO consider triggering SSE events for invalidations now that we can
   // calculate fine grained invalidations for from-scratch indexing by passing
   // in an onInvalidation callback
-  async fullIndex() {
+  async fullIndex(invalidateEntireRealm?: boolean) {
     this.#indexingDeferred = new Deferred<void>();
     try {
-      let args: WorkerArgs = {
+      let args: FromScratchArgs = {
         realmURL: this.#realm.url,
         realmUsername: await this.getRealmUsername(),
+        invalidateEntireRealm: Boolean(invalidateEntireRealm),
       };
       let job = await this.#queue.publish<FromScratchResult>(
         `from-scratch-index`,

packages/runtime-common/realm.ts

@@ -163,6 +163,7 @@ export interface RealmAdapter {
 
 interface Options {
   disableModuleCaching?: true;
+  invalidateEntireRealm?: true;
 }
 
 interface UpdateItem {
@@ -252,6 +253,7 @@ export class Realm {
   #recentWrites: Map<string, number> = new Map();
   #realmSecretSeed: string;
   #disableModuleCaching = false;
+  #invalidateEntireRealm = false;
 
   #publicEndpoints: RouteTable<true> = new Map([
     [
@@ -305,6 +307,7 @@ export class Realm {
       seed: secretSeed,
     });
     this.#disableModuleCaching = Boolean(opts?.disableModuleCaching);
+    this.#invalidateEntireRealm = Boolean(opts?.invalidateEntireRealm);
 
     let fetch = fetcher(virtualNetwork.fetch, [
       async (req, next) => {
@@ -591,7 +594,7 @@ export class Realm {
     await Promise.resolve();
     let startTime = Date.now();
     let isNewIndex = await this.#realmIndexUpdater.isNewIndex();
-    let promise = this.#realmIndexUpdater.run();
+    let promise = this.#realmIndexUpdater.run(this.#invalidateEntireRealm);
     if (isNewIndex) {
       // we only await the full indexing at boot if this is a brand new index
       await promise;