From ea70e16fcbf3efb5f4d2bc7063fbac7d7e2b4e59 Mon Sep 17 00:00:00 2001 From: Hassan Abdel-Rahman Date: Tue, 31 Dec 2024 10:58:57 -0500 Subject: [PATCH 1/7] debug perf logging --- packages/host/app/lib/current-run.ts | 33 ++++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) diff --git a/packages/host/app/lib/current-run.ts b/packages/host/app/lib/current-run.ts index e3d2d6f8c3..7e48f77c58 100644 --- a/packages/host/app/lib/current-run.ts +++ b/packages/host/app/lib/current-run.ts @@ -118,21 +118,43 @@ export class CurrentRun { static async fromScratch(current: CurrentRun): Promise { let start = Date.now(); log.debug(`starting from scratch indexing`); + console.log( + `starting from scratch indexing for realm ${current.realmURL.href}`, + ); current.#batch = await current.#indexWriter.createBatch(current.realmURL); + let mtimesStart = Date.now(); let mtimes = await current.batch.getModifiedTimes(); + console.log( + `completed getting index mtimes in ${Date.now() - mtimesStart} ms`, + ); + let invalidateStart = Date.now(); await current.discoverInvalidations(current.realmURL, mtimes); + console.log( + `completed invalidations in ${Date.now() - invalidateStart} ms`, + ); let invalidations = current.batch.invalidations.map( (href) => new URL(href), ); await current.whileIndexing(async () => { + let visitStart = Date.now(); for (let invalidation of invalidations) { await current.tryToVisit(invalidation); } + console.log(`completed index visit in ${Date.now() - visitStart} ms`); + let finalizeStart = Date.now(); let { totalIndexEntries } = await current.batch.done(); + console.log( + `completed index finalization in ${Date.now() - finalizeStart} ms`, + ); current.stats.totalIndexEntries = totalIndexEntries; log.debug(`completed from scratch indexing in ${Date.now() - start}ms`); + console.log( + `completed from scratch indexing for realm ${ + current.realmURL.href + } in ${Date.now() - start} ms`, + ); }); return { invalidations: [...(invalidations ?? [])].map((url) => url.href), @@ -231,15 +253,22 @@ export class CurrentRun { indexMtimes: LastModifiedTimes, ): Promise { log.debug(`discovering invalidations in dir ${url.href}`); + console.log(`discovering invalidations in dir ${url.href}`); + let ignoreStart = Date.now(); let ignorePatterns = await this.#reader.readFile( new URL('.gitignore', url), ); + console.log(`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(); + console.log( + `time to get file system mtimes ${Date.now() - mtimesStart} ms`, + ); 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 @@ -255,7 +284,11 @@ export class CurrentRun { indexEntry.lastModified == null || lastModified !== indexEntry.lastModified ) { + let invalidationStart = Date.now(); await this.batch.invalidate(new URL(url)); + console.log( + `time to invalidate ${url} ${Date.now() - invalidationStart} ms`, + ); } } } From e7ff304acc6415532c7b3c1bb1b57bf6841171f6 Mon Sep 17 00:00:00 2001 From: Hassan Abdel-Rahman Date: Tue, 31 Dec 2024 11:51:37 -0500 Subject: [PATCH 2/7] more debug perf logging --- packages/runtime-common/index-writer.ts | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/packages/runtime-common/index-writer.ts b/packages/runtime-common/index-writer.ts index cd0a378271..5f83114ac3 100644 --- a/packages/runtime-common/index-writer.ts +++ b/packages/runtime-common/index-writer.ts @@ -454,6 +454,7 @@ export class Batch { ): Promise< { url: string; alias: string; type: 'instance' | 'module' | 'error' }[] > { + let start = Date.now(); const pageSize = 1000; let results: (Pick & { type: 'instance' | 'module' | 'error'; @@ -488,6 +489,11 @@ export class Batch { results = [...results, ...rows]; pageNumber++; } while (rows.length === pageSize); + console.log( + `time to determine items that reference ${resolvedPath} ${ + Date.now() - start + } ms`, + ); return results.map(({ url, file_alias, type }) => ({ url, alias: file_alias, From d7d1562ef6d02f79568f2d4e8f0bbd32998c54b3 Mon Sep 17 00:00:00 2001 From: Hassan Abdel-Rahman Date: Wed, 8 Jan 2025 14:27:40 -0500 Subject: [PATCH 3/7] optimize invalidations --- packages/host/app/lib/current-run.ts | 39 ++++++++++++++++++------- packages/runtime-common/index-writer.ts | 19 +++++------- 2 files changed, 37 insertions(+), 21 deletions(-) diff --git a/packages/host/app/lib/current-run.ts b/packages/host/app/lib/current-run.ts index ee8a0d9832..af9558d915 100644 --- a/packages/host/app/lib/current-run.ts +++ b/packages/host/app/lib/current-run.ts @@ -135,13 +135,12 @@ export class CurrentRun { `completed getting index mtimes in ${Date.now() - mtimesStart} ms`, ); let invalidateStart = Date.now(); - await current.discoverInvalidations(current.realmURL, mtimes); + let invalidations = ( + await current.discoverInvalidations(current.realmURL, mtimes) + ).map((href) => new URL(href)); console.log( `completed invalidations in ${Date.now() - invalidateStart} ms`, ); - let invalidations = current.batch.invalidations.map( - (href) => new URL(href), - ); await current.whileIndexing(async () => { let visitStart = Date.now(); @@ -257,7 +256,7 @@ export class CurrentRun { private async discoverInvalidations( url: URL, indexMtimes: LastModifiedTimes, - ): Promise { + ): Promise { log.debug(`discovering invalidations in dir ${url.href}`); console.log(`discovering invalidations in dir ${url.href}`); let ignoreStart = Date.now(); @@ -275,6 +274,8 @@ export class CurrentRun { console.log( `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 @@ -290,13 +291,31 @@ export class CurrentRun { indexEntry.lastModified == null || lastModified !== indexEntry.lastModified ) { - let invalidationStart = Date.now(); - await this.batch.invalidate(new URL(url)); - console.log( - `time to invalidate ${url} ${Date.now() - invalidationStart} ms`, - ); + 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 + console.log( + `entire realm ${this.realmURL.href} is invalidated--skipping invalidation calculation`, + ); + return invalidationList; + } + + console.log( + `unable to use optimized invalidation for realm ${ + this.realmURL.href + }, skipped these files ${JSON.stringify(skipList)}`, + ); + let invalidationStart = Date.now(); + await this.batch.invalidate(new URL(url)); + console.log( + `time to invalidate ${url} ${Date.now() - invalidationStart} ms`, + ); + return this.batch.invalidations; } private async visitFile( diff --git a/packages/runtime-common/index-writer.ts b/packages/runtime-common/index-writer.ts index 1119858282..e76f331b17 100644 --- a/packages/runtime-common/index-writer.ts +++ b/packages/runtime-common/index-writer.ts @@ -496,6 +496,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}`, @@ -528,17 +531,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, From 2ab7cb1498cc5ce1ecbd0487cea003f244ba007e Mon Sep 17 00:00:00 2001 From: Hassan Abdel-Rahman Date: Wed, 8 Jan 2025 14:34:22 -0500 Subject: [PATCH 4/7] forgot to loop over files that were detected for invalidation --- packages/host/app/lib/current-run.ts | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/packages/host/app/lib/current-run.ts b/packages/host/app/lib/current-run.ts index af9558d915..fa084bbaf1 100644 --- a/packages/host/app/lib/current-run.ts +++ b/packages/host/app/lib/current-run.ts @@ -311,7 +311,9 @@ export class CurrentRun { }, skipped these files ${JSON.stringify(skipList)}`, ); let invalidationStart = Date.now(); - await this.batch.invalidate(new URL(url)); + for (let invalidationURL of invalidationList) { + await this.batch.invalidate(new URL(invalidationURL)); + } console.log( `time to invalidate ${url} ${Date.now() - invalidationStart} ms`, ); From d377ca21bff86526c9bf340cff1aafc2d42acf40 Mon Sep 17 00:00:00 2001 From: Hassan Abdel-Rahman Date: Wed, 8 Jan 2025 16:06:13 -0500 Subject: [PATCH 5/7] Add param to force invalidation of entire realm to from-scratch-job --- .../host/app/components/card-prerender.gts | 43 +++++++++----- packages/host/app/lib/current-run.ts | 58 ++++++++++++------- packages/host/app/services/local-indexer.ts | 5 +- packages/realm-server/server.ts | 25 ++++---- .../runtime-common/realm-index-updater.ts | 7 ++- packages/runtime-common/realm.ts | 5 +- packages/runtime-common/worker.ts | 18 +++++- 7 files changed, 105 insertions(+), 56 deletions(-) diff --git a/packages/host/app/components/card-prerender.gts b/packages/host/app/components/card-prerender.gts index c2c9fb1ed0..dd7a6ab915 100644 --- a/packages/host/app/components/card-prerender.gts +++ b/packages/host/app/components/card-prerender.gts @@ -52,9 +52,15 @@ export default class CardPrerender extends Component { } } - private async fromScratch(realmURL: URL): Promise { + private async fromScratch( + realmURL: URL, + invalidateEntireRealm: boolean, + ): Promise { 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 ( diff --git a/packages/host/app/lib/current-run.ts b/packages/host/app/lib/current-run.ts index fa084bbaf1..5d12106234 100644 --- a/packages/host/app/lib/current-run.ts +++ b/packages/host/app/lib/current-run.ts @@ -121,7 +121,10 @@ export class CurrentRun { this.#render = render; } - static async fromScratch(current: CurrentRun): Promise { + static async fromScratch( + current: CurrentRun, + invalidateEntireRealm?: boolean, + ): Promise { let start = Date.now(); log.debug(`starting from scratch indexing`); console.log( @@ -129,18 +132,39 @@ export class CurrentRun { ); current.#batch = await current.#indexWriter.createBatch(current.realmURL); - let mtimesStart = Date.now(); - let mtimes = await current.batch.getModifiedTimes(); - console.log( - `completed getting index mtimes in ${Date.now() - mtimesStart} ms`, - ); - let invalidateStart = Date.now(); - let invalidations = ( - await current.discoverInvalidations(current.realmURL, mtimes) - ).map((href) => new URL(href)); - console.log( - `completed invalidations in ${Date.now() - invalidateStart} ms`, - ); + let invalidations: URL[] = []; + if (invalidateEntireRealm) { + console.log( + `flag was set to invalidate entire realm ${current.realmURL.href}, skipping invalidation discovery`, + ); + let mtimesStart = Date.now(); + let filesystemMtimes = await current.#reader.mtimes(); + console.log( + `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(); + console.log( + `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)); + console.log( + `completed invalidations in ${Date.now() - invalidateStart} ms`, + ); + } await current.whileIndexing(async () => { let visitStart = Date.now(); @@ -299,17 +323,9 @@ export class CurrentRun { if (skipList.length === 0) { // the whole realm needs to be visited, no need to calculate // invalidations--it's everything - console.log( - `entire realm ${this.realmURL.href} is invalidated--skipping invalidation calculation`, - ); return invalidationList; } - console.log( - `unable to use optimized invalidation for realm ${ - this.realmURL.href - }, skipped these files ${JSON.stringify(skipList)}`, - ); let invalidationStart = Date.now(); for (let invalidationURL of invalidationList) { await this.batch.invalidate(new URL(invalidationURL)); diff --git a/packages/host/app/services/local-indexer.ts b/packages/host/app/services/local-indexer.ts index 3c0215a3d0..edf4238c9c 100644 --- a/packages/host/app/services/local-indexer.ts +++ b/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, + _fromScratch: ( + realmURL: URL, + invalidateEntireRealm: boolean, + ) => Promise, _incremental: ( url: URL, realmURL: URL, diff --git a/packages/realm-server/server.ts b/packages/realm-server/server.ts index ec78a70285..764ccbd277 100644 --- a/packages/realm-server/server.ts +++ b/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; diff --git a/packages/runtime-common/realm-index-updater.ts b/packages/runtime-common/realm-index-updater.ts index be1cbda24f..104f05b870 100644 --- a/packages/runtime-common/realm-index-updater.ts +++ b/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, @@ -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(); try { - let args: WorkerArgs = { + let args: FromScratchArgs = { realmURL: this.#realm.url, realmUsername: await this.getRealmUsername(), + invalidateEntireRealm: Boolean(invalidateEntireRealm), }; let job = await this.#queue.publish( `from-scratch-index`, diff --git a/packages/runtime-common/realm.ts b/packages/runtime-common/realm.ts index 837429bafe..395c0bd19d 100644 --- a/packages/runtime-common/realm.ts +++ b/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 = new Map(); #realmSecretSeed: string; #disableModuleCaching = false; + #invalidateEntireRealm = false; #publicEndpoints: RouteTable = 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) => { @@ -450,7 +453,7 @@ export class Realm { } async fullIndex() { - await this.realmIndexUpdater.fullIndex(); + await this.realmIndexUpdater.fullIndex(this.#invalidateEntireRealm); } async flushUpdateEvents() { diff --git a/packages/runtime-common/worker.ts b/packages/runtime-common/worker.ts index 767bacfbb1..ebeb6fc0e9 100644 --- a/packages/runtime-common/worker.ts +++ b/packages/runtime-common/worker.ts @@ -39,7 +39,10 @@ export interface Reader { } export type RunnerRegistration = ( - fromScratch: (realmURL: URL) => Promise, + fromScratch: ( + realmURL: URL, + invalidateEntireRealm: boolean, + ) => Promise, incremental: ( url: URL, realmURL: URL, @@ -72,6 +75,10 @@ export interface IncrementalResult { stats: Stats; } +export interface FromScratchArgs extends WorkerArgs { + invalidateEntireRealm: boolean; +} + export interface FromScratchResult extends JSONTypes.Object { ignoreData: Record; stats: Stats; @@ -119,7 +126,11 @@ export class Worker { #matrixClientCache: Map = new Map(); #secretSeed: string; #fromScratch: - | ((realmURL: URL, boom?: true) => Promise) + | (( + realmURL: URL, + invalidateEntireRealm: boolean, + boom?: true, + ) => Promise) | undefined; #incremental: | (( @@ -239,13 +250,14 @@ export class Worker { return result; } - private fromScratch = async (args: WorkerArgs) => { + private fromScratch = async (args: FromScratchArgs) => { return await this.prepareAndRunJob(args, async () => { if (!this.#fromScratch) { throw new Error(`Index runner has not been registered`); } let { ignoreData, stats } = await this.#fromScratch( new URL(args.realmURL), + args.invalidateEntireRealm, ); return { ignoreData: { ...ignoreData }, From 4d04536c2b4bd6e37faf2f996677fdad97d7f515 Mon Sep 17 00:00:00 2001 From: Hassan Abdel-Rahman Date: Wed, 8 Jan 2025 17:24:40 -0500 Subject: [PATCH 6/7] threaded flag to use optimized from scratch indexing and using logger instead of console.log --- packages/host/app/lib/current-run.ts | 25 ++++++++++--------- packages/runtime-common/index-writer.ts | 4 ++- .../runtime-common/realm-index-updater.ts | 4 +-- packages/runtime-common/realm.ts | 4 +-- 4 files changed, 20 insertions(+), 17 deletions(-) diff --git a/packages/host/app/lib/current-run.ts b/packages/host/app/lib/current-run.ts index 5d12106234..686017c97e 100644 --- a/packages/host/app/lib/current-run.ts +++ b/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; @@ -127,19 +128,19 @@ export class CurrentRun { ): Promise { let start = Date.now(); log.debug(`starting from scratch indexing`); - console.log( + perfLog.debug( `starting from scratch indexing for realm ${current.realmURL.href}`, ); current.#batch = await current.#indexWriter.createBatch(current.realmURL); let invalidations: URL[] = []; if (invalidateEntireRealm) { - console.log( + 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(); - console.log( + perfLog.debug( `time to get file system mtimes ${Date.now() - mtimesStart} ms`, ); invalidations = Object.keys(filesystemMtimes) @@ -154,14 +155,14 @@ export class CurrentRun { } else { let mtimesStart = Date.now(); let mtimes = await current.batch.getModifiedTimes(); - console.log( + 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)); - console.log( + perfLog.debug( `completed invalidations in ${Date.now() - invalidateStart} ms`, ); } @@ -171,15 +172,15 @@ export class CurrentRun { for (let invalidation of invalidations) { await current.tryToVisit(invalidation); } - console.log(`completed index visit in ${Date.now() - visitStart} ms`); + perfLog.debug(`completed index visit in ${Date.now() - visitStart} ms`); let finalizeStart = Date.now(); let { totalIndexEntries } = await current.batch.done(); - console.log( + 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`); - console.log( + perfLog.debug( `completed from scratch indexing for realm ${ current.realmURL.href } in ${Date.now() - start} ms`, @@ -282,12 +283,12 @@ export class CurrentRun { indexMtimes: LastModifiedTimes, ): Promise { log.debug(`discovering invalidations in dir ${url.href}`); - console.log(`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), ); - console.log(`time to get ignore rules ${Date.now() - ignoreStart} ms`); + 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; @@ -295,7 +296,7 @@ export class CurrentRun { let mtimesStart = Date.now(); let filesystemMtimes = await this.#reader.mtimes(); - console.log( + perfLog.debug( `time to get file system mtimes ${Date.now() - mtimesStart} ms`, ); let invalidationList: string[] = []; @@ -330,7 +331,7 @@ export class CurrentRun { for (let invalidationURL of invalidationList) { await this.batch.invalidate(new URL(invalidationURL)); } - console.log( + perfLog.debug( `time to invalidate ${url} ${Date.now() - invalidationStart} ms`, ); return this.batch.invalidations; diff --git a/packages/runtime-common/index-writer.ts b/packages/runtime-common/index-writer.ts index e76f331b17..bbfdcbe097 100644 --- a/packages/runtime-common/index-writer.ts +++ b/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; #invalidations = new Set(); #dbAdapter: DBAdapter; + #perfLog = logger('index-perf'); private declare realmVersion: number; constructor( @@ -508,7 +510,7 @@ export class Batch { results = [...results, ...rows]; pageNumber++; } while (rows.length === pageSize); - console.log( + this.#perfLog.debug( `time to determine items that reference ${resolvedPath} ${ Date.now() - start } ms`, diff --git a/packages/runtime-common/realm-index-updater.ts b/packages/runtime-common/realm-index-updater.ts index 104f05b870..fbe2aacdc9 100644 --- a/packages/runtime-common/realm-index-updater.ts +++ b/packages/runtime-common/realm-index-updater.ts @@ -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() { diff --git a/packages/runtime-common/realm.ts b/packages/runtime-common/realm.ts index 395c0bd19d..eaf8fcf748 100644 --- a/packages/runtime-common/realm.ts +++ b/packages/runtime-common/realm.ts @@ -453,7 +453,7 @@ export class Realm { } async fullIndex() { - await this.realmIndexUpdater.fullIndex(this.#invalidateEntireRealm); + await this.realmIndexUpdater.fullIndex(); } async flushUpdateEvents() { @@ -594,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; From e8a615ed2d9d02e14969eb66d3b8d6b055a7a77a Mon Sep 17 00:00:00 2001 From: Hassan Abdel-Rahman Date: Wed, 8 Jan 2025 18:04:46 -0500 Subject: [PATCH 7/7] increasing threshold to 30 sec for realm creation time warning --- packages/realm-server/handlers/handle-create-realm.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/realm-server/handlers/handle-create-realm.ts b/packages/realm-server/handlers/handle-create-realm.ts index 2dd2af11c8..306eef6f9a 100644 --- a/packages/realm-server/handlers/handle-create-realm.ts +++ b/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, )}`;