spray a bunch of loggers

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

@@ -54,8 +54,10 @@ export default class CardPrerender extends Component {
   }
 
   private async fromScratch(realmURL: URL): Promise<RunState> {
+    console.log('fromScratch', realmURL.href);
     try {
       let state = await this.doFromScratch.perform(realmURL);
+      console.log('fromScratch finished');
       return state;
     } catch (e: any) {
       if (!didCancel(e)) {
@@ -73,6 +75,7 @@ export default class CardPrerender extends Component {
     operation: 'delete' | 'update',
     onInvalidation?: (invalidatedURLs: URL[]) => void,
   ): Promise<RunState> {
+    console.log('incremental started');
     if (hasExecutableExtension(url.href) && !this.fastboot.isFastBoot) {
       this.loaderService.reset();
     }
@@ -92,6 +95,8 @@ export default class CardPrerender extends Component {
     throw new Error(
       `card-prerender component is missing or being destroyed before incremental index of ${url} was completed`,
     );
+
+    console.log('incremental finished');
   }
 
   private warmUpModuleCache = dropTask(async () => {

packages/host/app/services/render-service.ts

@@ -57,6 +57,7 @@ export default class RenderService extends Service {
   owner: Owner = getOwner(this)!;
 
   async renderCard(params: RenderCardParams): Promise<string> {
+    console.log('renderCard called: ', params.card.id);
     let {
       card,
       visit,
@@ -120,6 +121,7 @@ export default class RenderService extends Service {
 
     let serializer = new Serializer(voidMap);
     let html = serializer.serialize(element);
+    console.log('renderCard finished');
     return parseCardHtml(html);
   }
 

packages/realm-server/package.json

@@ -73,8 +73,8 @@
     "start:drafts:root": "NODE_NO_WARNINGS=1 ts-node --transpileOnly main --port=4204 --path='../drafts-realm/' --toUrl='/' --fromUrl='https://cardstack.com/base/' --toUrl='http://localhost:4201/base/'",
     "start:all": "NODE_NO_WARNINGS=1 start-server-and-test 'run-p start:development start:base:root' 'http-get://localhost:4201/base/fields/boolean-field?acceptHeader=application%2Fvnd.card%2Bjson|http-get://localhost:4203/fields/boolean-field?acceptHeader=application%2Fvnd.card%2Bjson|http-get://localhost:4201/drafts/index?acceptHeader=application%2Fvnd.card%2Bjson' 'run-p start:test-realms start:test-container start:matrix start:smtp' 'http-get://localhost:4202/node-test/person-1?acceptHeader=application%2Fvnd.card%2Bjson|http-get://127.0.0.1:4205|http://localhost:8008|http://localhost:5001' 'wait'",
     "start:without-matrix": "NODE_NO_WARNINGS=1 start-server-and-test 'run-p start:development start:base:root' 'http-get://localhost:4201/base/fields/boolean-field?acceptHeader=application%2Fvnd.card%2Bjson|http-get://localhost:4203/fields/boolean-field?acceptHeader=application%2Fvnd.card%2Bjson|http-get://localhost:4201/drafts/index?acceptHeader=application%2Fvnd.card%2Bjson' 'run-p start:test-realms start:test-container' 'http-get://localhost:4202/node-test/person-1?acceptHeader=application%2Fvnd.card%2Bjson|http-get://127.0.0.1:4205' 'wait'",
-    "start:staging": "pnpm setup:base-in-deployment && pnpm setup:drafts-in-deployment && pnpm setup:published-in-deployment && NODE_NO_WARNINGS=1 LOG_LEVELS='*=info' ts-node --transpileOnly main --port=3000 --path='/persistent/base' --fromUrl='https://cardstack.com/base/' --toUrl='https://realms-staging.stack.cards/base/' --distURL='https://boxel-host-staging.stack.cards' --path='/persistent/drafts' --fromUrl='https://realms-staging.stack.cards/drafts/' --toUrl='https://realms-staging.stack.cards/drafts/' --path='/persistent/published' --fromUrl='https://realms-staging.stack.cards/published/' --toUrl='https://realms-staging.stack.cards/published/' --fromUrl='https://cardstack.com/base/' --toUrl='https://realms-staging.stack.cards/base/' --fromUrl='https://realms-staging.stack.card/base/' --toUrl='https://realms-staging.stack.cards/base/'",
-    "start:development": "pnpm setup:base-assets && NODE_NO_WARNINGS=1 LOG_LEVELS='*=info' ts-node --transpileOnly main --port=4201 --path='../base' --fromUrl='https://cardstack.com/base/' --toUrl='http://localhost:4201/base/' --path='../drafts-realm' --fromUrl='http://localhost:4201/drafts/' --toUrl='http://localhost:4201/drafts/' --path='../published-realm' --fromUrl='http://localhost:4201/published/' --toUrl='http://localhost:4201/published/'",
+    "start:staging": "pnpm setup:base-in-deployment && pnpm setup:drafts-in-deployment && pnpm setup:published-in-deployment && NODE_NO_WARNINGS=1 LOG_LEVELS='*=debug' ts-node --transpileOnly main --port=3000 --path='/persistent/base' --fromUrl='https://cardstack.com/base/' --toUrl='https://realms-staging.stack.cards/base/' --distURL='https://boxel-host-staging.stack.cards' --path='/persistent/drafts' --fromUrl='https://realms-staging.stack.cards/drafts/' --toUrl='https://realms-staging.stack.cards/drafts/' --path='/persistent/published' --fromUrl='https://realms-staging.stack.cards/published/' --toUrl='https://realms-staging.stack.cards/published/' --fromUrl='https://cardstack.com/base/' --toUrl='https://realms-staging.stack.cards/base/' --fromUrl='https://realms-staging.stack.card/base/' --toUrl='https://realms-staging.stack.cards/base/'",
+    "start:development": "pnpm setup:base-assets && NODE_NO_WARNINGS=1 LOG_LEVELS='*=debug' ts-node --transpileOnly main --port=4201 --path='../base' --fromUrl='https://cardstack.com/base/' --toUrl='http://localhost:4201/base/' --path='../drafts-realm' --fromUrl='http://localhost:4201/drafts/' --toUrl='http://localhost:4201/drafts/' --path='../published-realm' --fromUrl='http://localhost:4201/published/' --toUrl='http://localhost:4201/published/'",
     "start:production": "pnpm setup:base-in-deployment && pnpm setup:drafts-in-deployment && pnpm setup:published-in-deployment && NODE_NO_WARNINGS=1 LOG_LEVELS='*=info' ts-node --transpileOnly main --port=3000 --distURL='https://boxel-host.cardstack.com' --path='/persistent/base' --fromUrl='https://cardstack.com/base/' --toUrl='https://realms.cardstack.com/base/' --path='/persistent/drafts' --fromUrl='https://realms.cardstack.com/drafts/' --toUrl='https://realms.cardstack.com/drafts/' --path='/persistent/published' --fromUrl='https://realms.cardstack.com/published/' --toUrl='https://realms.cardstack.com/published/' --fromUrl='https://cardstack.com/base/' --toUrl='https://realms.cardstack.com/base/' --fromUrl='https://realms.cardstack.com/base/' --toUrl='https://realms.cardstack.com/base/'",
     "wait": "sleep 10000000",
     "lint": "glint"

packages/runtime-common/log.ts

@@ -12,7 +12,7 @@ import LogLevel, { type LogLevelDesc } from 'loglevel';
  *    app:index all done
  */
 
-const DEFAULT_LOG_LEVEL = 'info';
+const DEFAULT_LOG_LEVEL = 'debug';
 
 const validLevels = [
   'trace',

packages/runtime-common/realm.ts

@@ -311,6 +311,7 @@ export class Realm {
   // each other we use a queue of operations to mutate realm state. We should
   // remove this queue when we move to a pg backed index
   private async drainOperations() {
+    this.#log.debug('drainOperations called'); // remove after debugging slow card source writing
     await this.#flushOperations;
 
     let operationsDrained: () => void;
@@ -320,6 +321,7 @@ export class Realm {
     let operations = [...this.#operationQueue];
     this.#operationQueue = [];
     for (let operation of operations) {
+      this.#log.debug(`processing operation`, JSON.stringify(operation)); // remove after debugging slow card source writing
       if (operation.type === 'write') {
         let result = await this.#write(operation.path, operation.contents);
         operation.deferred.fulfill(result);
@@ -329,10 +331,12 @@ export class Realm {
       }
     }
 
+    this.#log.debug(`calling operationsDrained`); // remove after debugging slow card source writing
     operationsDrained!();
   }
 
   async write(path: LocalPath, contents: string): Promise<WriteResult> {
+    this.#log.debug('write called'); // remove after debugging slow card source writing
     let deferred = new Deferred<WriteResult>();
     this.#operationQueue.push({
       type: 'write',
@@ -341,12 +345,17 @@ export class Realm {
       deferred,
     });
     this.drainOperations();
+    this.#log.debug(`operations drained done`); // remove after debugging slow card source writing
     return deferred.promise;
   }
 
   async #write(path: LocalPath, contents: string): Promise<WriteResult> {
+    this.#log.debug(`#write called`, JSON.stringify({ path, contents })); // remove after debugging slow card source writing
     await this.trackOwnWrite(path);
+
+    this.#log.debug(`#adapter.write called`); // remove after debugging slow card source writing
     let results = await this.#adapter.write(path, contents);
+    this.#log.debug(`updating search index`); // remove after debugging slow card source writing
     await this.#searchIndex.update(this.paths.fileURL(path), {
       onInvalidation: (invalidatedURLs: URL[]) => {
         this.sendServerEvent({
@@ -358,11 +367,14 @@ export class Realm {
         });
       },
     });
+
+    this.#log.debug(`updating search index done`); // remove after debugging slow card source writing
     return results;
   }
 
   // we track our own writes so that we can eliminate echoes in the file watcher
   private async trackOwnWrite(path: LocalPath, opts?: { isDelete: true }) {
+    this.#log.debug(`trackOwnWrite called`); // remove after debugging slow card source writing
     let type = opts?.isDelete
       ? 'removed'
       : (await this.#adapter.exists(path))
@@ -603,6 +615,8 @@ export class Realm {
   }
 
   private async upsertCardSource(request: Request): Promise<Response> {
+    this.#log.debug('upsertCardSource called'); // remove after debugging slow card source writing
+
     let { lastModified } = await this.write(
       this.paths.local(request.url),
       await request.text(),

packages/runtime-common/search-index.ts

@@ -5,6 +5,7 @@ import {
   maxLinkDepth,
   maybeURL,
   type LooseCardResource,
+  logger,
 } from '.';
 import { Kind, Realm } from './realm';
 import { LocalPath, RealmPaths } from './paths';
@@ -225,10 +226,12 @@ export class SearchIndex {
     url: URL,
     opts?: { delete?: true; onInvalidation?: (invalidatedURLs: URL[]) => void },
   ): Promise<void> {
+    logger('realm').debug(`search index update called`); // remove after debugging slow card source writing
     await this.setupRunner(async () => {
       if (!this.#incremental) {
         throw new Error(`Index runner has not been registered`);
       }
+      logger('realm').debug(`calling #incremental`); // remove after debugging slow card source writing
       let current = await this.#incremental(
         this.#index,
         url,
@@ -247,6 +250,7 @@ export class SearchIndex {
         stats: current.stats,
         loader: Loader.cloneLoader(this.#realm.loader),
       };
+      logger('realm').debug(`search index update finished`); // remove after debugging slow card source writing
     });
   }