Temporarily add timings to see how long DB resets take.

Author: GrantDLS

apps/backend/src/datasources/postgres/AdminDataSource.ts

@@ -43,6 +43,8 @@ import {
 const dbPatchesFolderPath = path.join(cwd(), 'db_patches');
 const seedsPath = path.join(dbPatchesFolderPath, 'db_seeds');
 
+const getDurationMs = (startedAt: number) => Date.now() - startedAt;
+
 @injectable()
 export default class PostgresAdminDataSource implements AdminDataSource {
   private autoUpgradedDBReady = false;
@@ -280,20 +282,38 @@ export default class PostgresAdminDataSource implements AdminDataSource {
    * NB! This will actually wipe the database
    */
   async resetDB(includeSeeds: boolean) {
+    const resetStartedAt = Date.now();
+    const shouldApplySeeds = env.INCLUDE_SEEDS === '1' || includeSeeds;
+
     try {
+      const dropSchemaStartedAt = Date.now();
+
       await database.raw(`
         DROP SCHEMA public CASCADE;
         CREATE SCHEMA public;
         GRANT ALL ON SCHEMA public TO duouser;
         GRANT ALL ON SCHEMA public TO public;
       `);
 
+      logger.logInfo('resetDB timing: schema recreated', {
+        durationMs: getDurationMs(dropSchemaStartedAt),
+        includeSeeds,
+        shouldApplySeeds,
+      });
+
       const applyPatchesOutput = await this.applyPatches();
 
-      if (env.INCLUDE_SEEDS === '1' || includeSeeds) {
+      if (shouldApplySeeds) {
         await this.applySeeds();
       }
 
+      logger.logInfo('resetDB timing: reset finished', {
+        durationMs: getDurationMs(resetStartedAt),
+        includeSeeds,
+        shouldApplySeeds,
+        patchesApplied: applyPatchesOutput.length,
+      });
+
       return applyPatchesOutput;
     } catch (e) {
       logger.logException('resetDB failed', e);
@@ -304,6 +324,7 @@ export default class PostgresAdminDataSource implements AdminDataSource {
 
   async applyPatches(): Promise<string[]> {
     this.autoUpgradedDBReady = false;
+    const applyPatchesStartedAt = Date.now();
 
     logger.logInfo('Applying patches started', { timestamp: new Date() });
 
@@ -337,14 +358,19 @@ export default class PostgresAdminDataSource implements AdminDataSource {
       });
     }
 
-    logger.logInfo('Applying patches finished', { timestamp: new Date() });
+    logger.logInfo('Applying patches finished', {
+      timestamp: new Date(),
+      durationMs: getDurationMs(applyPatchesStartedAt),
+      patchesApplied: patches.length,
+    });
 
     this.autoUpgradedDBReady = true;
 
     return patches.map(([file]) => file);
   }
 
   private async applySeeds() {
+    const applySeedsStartedAt = Date.now();
     logger.logInfo('Applying seeds started', { timestamp: new Date() });
 
     const log: string[] = [];
@@ -372,7 +398,10 @@ export default class PostgresAdminDataSource implements AdminDataSource {
         });
     }
 
-    logger.logInfo('Applying seeds finished', {});
+    logger.logInfo('Applying seeds finished', {
+      durationMs: getDurationMs(applySeedsStartedAt),
+      seedsApplied: log.length,
+    });
   }
 
   protected async upgrade() {

apps/backend/src/mutations/AdminMutations.ts

@@ -28,6 +28,8 @@ import { signToken } from '../utils/jwt';
 import { ApolloServerErrorCodeExtended } from '../utils/utilTypes';
 
 const IS_BACKEND_VALIDATION = true;
+const getDurationMs = (startedAt: number) => Date.now() - startedAt;
+
 @injectable()
 export default class AdminMutations {
   constructor(
@@ -44,11 +46,23 @@ export default class AdminMutations {
     } else {
       logger.logWarn('Resetting database', {});
 
+      const resetStartedAt = Date.now();
       const log = await this.dataSource.resetDB(includeSeeds);
+      const configureEnvironmentStartedAt = Date.now();
+
       await container.resolve<() => Promise<void>>(
         Tokens.ConfigureEnvironment
       )();
 
+      logger.logInfo('resetDB timing: environment configured', {
+        durationMs: getDurationMs(configureEnvironmentStartedAt),
+        includeSeeds,
+      });
+      logger.logInfo('resetDB timing: mutation finished', {
+        durationMs: getDurationMs(resetStartedAt),
+        includeSeeds,
+      });
+
       return log;
     }
   }