Record async migration execution time

Needs a migration of existing `migration status` tables to introduce `execution time` column.

Change-type: minor
Signed-off-by: fisehara <[email protected]>

src/migrator/async.ts

@@ -122,7 +122,7 @@ const $run = async (
 		let asyncRunnerMigratorFn: (tx: Tx) => Promise<number>;
 		let initMigrationState: InitialMigrationStatus = {
 			migration_key: key,
-			start_time: new Date(),
+			execution_time: 0,
 			last_run_time: new Date(),
 			run_count: 0,
 			migrated_row_count: 0,
@@ -229,11 +229,14 @@ const $run = async (
 								try {
 									// here a separate transaction is needed as this migration may fail
 									// when it fails it would break the transaction for managing the migration status
+									const executionStartTimeMS = Date.now();
 									const migratedRows = await sbvrUtils.db.transaction(
 										async (migrationTx) => {
 											return (await asyncRunnerMigratorFn?.(migrationTx)) ?? 0;
 										},
 									);
+									migrationState.execution_time =
+										Date.now() - executionStartTimeMS;
 									migrationState.migrated_row_count += migratedRows;
 									if (migratedRows === 0) {
 										// when all rows have been catched up once we only catch up less frequently
@@ -250,7 +253,7 @@ const $run = async (
 									if (err instanceof Error) {
 										if (
 											migrationState.error_count %
-											initMigrationState.errorThreshold ===
+												initMigrationState.errorThreshold ===
 											0
 										) {
 											(sbvrUtils.api.migrations?.logger.error ?? console.error)(

src/migrator/migrations.sbvr

@@ -24,8 +24,8 @@ Fact Type: migration lock has model name
 
 Term: migration key
 	Concept Type: Short Text (Type)
-Term: start time
-	Concept Type: Date Time (Type)
+Term: execution time
+	Concept Type: Integer (Type)
 Term: last run time
 	Concept Type: Date Time (Type)
 Term: run count
@@ -45,8 +45,8 @@ Term: migration status
 Fact Type: migration status has migration key
 	Necessity: each migration status has exactly one migration key
 
-Fact Type: migration status has start time
-	Necessity: each migration status has at most one start time
+Fact Type: migration status has execution time
+	Necessity: each migration status has at most one execution time
 
 Fact Type: migration status has last run time
 	Necessity: each migration status has at most one last run time

src/migrator/utils.ts

@@ -87,7 +87,7 @@ export class MigrationError extends TypedError {}
 
 export type MigrationStatus = {
 	migration_key: string;
-	start_time: Date;
+	execution_time: number;
 	last_run_time: Date | null;
 	run_count: number;
 	migrated_row_count: number;
@@ -283,13 +283,13 @@ export const initMigrationStatus = async (
 	try {
 		return await tx.executeSql(
 			binds`
-INSERT INTO "migration status" ("migration key", "start time", "is backing off", "run count")
+INSERT INTO "migration status" ("migration key", "execution time", "is backing off", "run count")
 SELECT ${1}, ${2}, ${3}, ${4}
 WHERE NOT EXISTS (SELECT 1 FROM "migration status" WHERE "migration key" = ${5})
 `,
 			[
 				migrationStatus['migration_key'],
-				migrationStatus['start_time'],
+				migrationStatus['execution_time'],
 				migrationStatus['is_backing_off'] ? 1 : 0,
 				migrationStatus['run_count'],
 				migrationStatus['migration_key'],
@@ -316,15 +316,17 @@ SET
 "migrated row count" = ${3},
 "error count" = ${4},
 "converged time" = ${5},
-"is backing off" = ${6}
-WHERE "migration status"."migration key" = ${7};`,
+"is backing off" = ${6},
+"execution time" = ${7}
+WHERE "migration status"."migration key" = ${8};`,
 			[
 				migrationStatus['run_count'],
 				migrationStatus['last_run_time'],
 				migrationStatus['migrated_row_count'],
 				migrationStatus['error_count'],
 				migrationStatus['converged_time'],
 				migrationStatus['is_backing_off'] ? 1 : 0,
+				migrationStatus['execution_time'],
 				migrationStatus['migration_key'],
 			],
 		);
@@ -355,7 +357,7 @@ LIMIT 1;`,
 
 		return {
 			migration_key: data['migration key'],
-			start_time: data['start time'],
+			execution_time: data['execution time'],
 			last_run_time: data['last run time'],
 			run_count: data['run count'],
 			migrated_row_count: data['migrated row count'],

test/03-async-migrator.test.ts

@@ -202,6 +202,22 @@ describe('03 Async Migrations', async function () {
 			expect(result[0]?.migrated_row_count - firstRowsMigrated).to.equal(1);
 			expect(Date.now().valueOf() - startTime).to.be.greaterThan(4000); // backOff time from migrator
 		});
+
+		it.only('should record execution time of the last migration run', async function () {
+			let result: MigrationStatus[] = [];
+
+			const startTime = Date.now().valueOf();
+			// Wait until all migrations have run at least once
+			while (result.length === 0 || !result.every((row) => row.run_count > 0)) {
+				result = await getMigrationStatus();
+			}
+
+			const checkMigration0003 = result.find(
+				(row) => row.migration_key === '0003',
+			);
+			expect(checkMigration0003?.execution_time).to.be.greaterThan(500); // should be reported greater than 500 ms (from the async migration function)
+			expect(checkMigration0003?.execution_time).to.be.lessThan(2 * 500); // should not exceed twice the execution time defined in the async migration function
+		});
 	});
 
 	describe('Init sync and async migrations for new model', function () {

test/fixtures/03-async-migrator/01-migrations/migrations/0003-test-migration-execution.async.ts

@@ -0,0 +1,18 @@
+import { AsyncMigration } from '../../../../../src/migrator/utils';
+
+const migration: AsyncMigration = {
+	asyncFn: async (tx, options) => {
+		options;
+		return await tx.executeSql(`SELECT pg_sleep(0.5);`);
+	},
+	asyncBatchSize: 1,
+	syncFn: async (tx) => {
+		await tx.executeSql(`SELECT pg_sleep(0.5);`);
+	},
+	delayMS: 1000,
+	backoffDelayMS: 4000,
+	errorThreshold: 15,
+	finalize: false,
+};
+
+export default migration;