chore: refactor: replace calls to Date.now() -> startTime()

shared/packages/api/src/lib.ts

@@ -57,10 +57,10 @@ export async function promiseTimeout<T>(
 	timeoutTime: number,
 	timeoutMessage?: string | ((timeoutDuration: number) => string)
 ): Promise<T> {
-	const startTime = Date.now()
+	const timer = startTimer()
 	return new Promise<T>((resolve, reject) => {
 		const timeout = setTimeout(() => {
-			const duration = Date.now() - startTime
+			const duration = timer.get()
 			const msg = typeof timeoutMessage === 'function' ? timeoutMessage(duration) : timeoutMessage
 			reject(msg || 'Timeout')
 		}, timeoutTime)
@@ -343,3 +343,21 @@ export function findValue<K, V>(map: Map<K, V>, cb: (key: K, value: V) => boolea
 	if (found === undefined) return undefined
 	return found[1]
 }
+/**
+ * Usage:
+ * const timer = startTimer()
+ * // do stuff
+ * const duration = timer.get()
+ */
+export function startTimer(): {
+	/** Returns the duration since the timer started, in milliseconds */
+	get: () => number
+} {
+	const startTime = Date.now()
+
+	return {
+		get: () => {
+			return Date.now() - startTime
+		},
+	}
+}

shared/packages/expectationManager/src/evaluationRunner/evaluationRunner.ts

@@ -10,6 +10,7 @@ import {
 	Reason,
 	StatusCode,
 	stringifyError,
+	startTimer,
 } from '@sofie-package-manager/api'
 import { PromisePool } from '@supercharge/promise-pool'
 import _ from 'underscore'
@@ -38,29 +39,41 @@ export class EvaluationRunner {
 	public async run(): Promise<EvaluationResult> {
 		this.logger.debug(Date.now() / 1000 + ' _evaluateExpectations ----------')
 
-		let startTime = Date.now()
 		const times: { [key: string]: number } = {}
 
-		// First we're going to see if there is any new incoming data which needs to be pulled in.
-		if (this.tracker.receivedUpdates.expectationsHasBeenUpdated) {
-			await this.updateReceivedData_Expectations().promise
+		{
+			const timer = startTimer()
+
+			// First we're going to see if there is any new incoming data which needs to be pulled in.
+			if (this.tracker.receivedUpdates.expectationsHasBeenUpdated) {
+				await this.updateReceivedData_Expectations().promise
+			}
+			times['timeUpdateReceivedExpectations'] = timer.get()
 		}
-		times['timeUpdateReceivedExpectations'] = Date.now() - startTime
-		startTime = Date.now()
 
-		if (this.tracker.receivedUpdates.packageContainersHasBeenUpdated) {
-			await this._updateReceivedData_TrackedPackageContainers()
+		{
+			const timer = startTimer()
+
+			if (this.tracker.receivedUpdates.packageContainersHasBeenUpdated) {
+				await this._updateReceivedData_TrackedPackageContainers()
+			}
+			times['timeUpdateReceivedPackageContainerExpectations'] = timer.get()
 		}
-		times['timeUpdateReceivedPackageContainerExpectations'] = Date.now() - startTime
-		startTime = Date.now()
 
-		// Iterate through the PackageContainerExpectations:
-		await this._evaluateAllTrackedPackageContainers()
-		times['timeEvaluateAllTrackedPackageContainers'] = Date.now() - startTime
-		startTime = Date.now()
+		{
+			const timer = startTimer()
 
-		this.tracker.worksInProgress.checkWorksInProgress()
-		times['timeMonitorWorksInProgress'] = Date.now() - startTime
+			// Iterate through the PackageContainerExpectations:
+			await this._evaluateAllTrackedPackageContainers()
+			times['timeEvaluateAllTrackedPackageContainers'] = timer.get()
+		}
+
+		{
+			const timer = startTimer()
+
+			this.tracker.worksInProgress.checkWorksInProgress()
+			times['timeMonitorWorksInProgress'] = timer.get()
+		}
 
 		// Iterate through all Expectations:
 		const { runAgainASAP, times: evaluateTimes } = await this._evaluateAllExpectations()
@@ -298,7 +311,7 @@ export class EvaluationRunner {
 
 		// Step 1: Evaluate the Expectations which are in the states that can be handled in parallel:
 		for (const handleState of handleStatesParallel) {
-			const startTime = Date.now()
+			const timer = startTimer()
 			// Filter out the ones that are in the state we're about to handle:
 			const trackedWithState = tracked.filter((trackedExp) => trackedExp.state === handleState)
 
@@ -324,7 +337,7 @@ export class EvaluationRunner {
 						postProcessSession(trackedExp)
 					})
 			}
-			times[`time_${handleState}`] = Date.now() - startTime
+			times[`time_${handleState}`] = timer.get()
 		}
 
 		// Step 1.5: Reset the session:
@@ -340,7 +353,7 @@ export class EvaluationRunner {
 		})
 		this.logger.debug(`Worker count: ${this.manager.workerAgents.list().length}`)
 
-		const startTime = Date.now()
+		const timer = startTimer()
 		// Step 2: Evaluate the expectations, now one by one:
 		for (const trackedExp of tracked) {
 			// Only handle the states that
@@ -350,7 +363,7 @@ export class EvaluationRunner {
 				postProcessSession(trackedExp)
 			}
 
-			if (runAgainASAP && Date.now() - startTime > this.tracker.constants.ALLOW_SKIPPING_QUEUE_TIME) {
+			if (runAgainASAP && timer.get() > this.tracker.constants.ALLOW_SKIPPING_QUEUE_TIME) {
 				// Skip the rest of the queue, so that we don't get stuck on evaluating low-prio expectations.
 				this.logger.debug(
 					`Skipping the rest of the queue (after ${this.tracker.constants.ALLOW_SKIPPING_QUEUE_TIME})`
@@ -365,7 +378,7 @@ export class EvaluationRunner {
 				break
 			}
 		}
-		times[`time_restTrackedExp`] = Date.now() - startTime
+		times[`time_restTrackedExp`] = timer.get()
 		for (const id of removeIds) {
 			this.tracker.trackedExpectations.remove(id)
 		}
@@ -495,7 +508,7 @@ export class EvaluationRunner {
 	}
 	private async _evaluateAllTrackedPackageContainers(): Promise<void> {
 		for (const trackedPackageContainer of this.tracker.trackedPackageContainers.list()) {
-			const startTime = Date.now()
+			const timer = startTimer()
 
 			try {
 				let badStatus = false
@@ -708,9 +721,7 @@ export class EvaluationRunner {
 					}
 				)
 			}
-			this.logger.debug(
-				`trackedPackageContainer ${trackedPackageContainer.id}, took ${Date.now() - startTime} ms`
-			)
+			this.logger.debug(`trackedPackageContainer ${trackedPackageContainer.id}, took ${timer.get()} ms`)
 		}
 	}
 }

shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/fileCopyProxy.ts

@@ -32,6 +32,7 @@ import {
 import { doFileCopyExpectation, isFileFulfilled, isFileReadyToStartWorkingOn } from './lib/file'
 import { getSourceHTTPHandle } from './lib/quantel'
 import { FFMpegProcess, spawnFFMpeg } from './lib/ffmpeg'
+import { startTimer } from '@sofie-package-manager/api'
 
 /**
  * Copies a file from one of the sources and into the target PackageContainer.
@@ -90,7 +91,7 @@ export const FileCopyProxy: ExpectationWindowsHandler = {
 			const sourceHandle = lookupSource.handle
 			const targetHandle = lookupTarget.handle
 
-			const startTime = Date.now()
+			const timer = startTimer()
 
 			if (
 				lookupSource.accessor.type === Accessor.AccessType.QUANTEL &&
@@ -142,7 +143,7 @@ export const FileCopyProxy: ExpectationWindowsHandler = {
 							await targetHandle.finalizePackage(fileOperation)
 							await targetHandle.updateMetadata(actualSourceUVersion)
 
-							const duration = Date.now() - startTime
+							const duration = timer.get()
 							wip._reportComplete(
 								actualSourceVersionHash,
 								{

shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/jsonDataCopy.ts

@@ -21,6 +21,7 @@ import {
 import { IWorkInProgress, WorkInProgress } from '../../../lib/workInProgress'
 import { checkWorkerHasAccessToPackageContainersOnPackage, lookupAccessorHandles, LookupPackageContainer } from './lib'
 import { PackageReadStream, PutPackageHandler } from '../../../accessorHandlers/genericHandle'
+import { startTimer } from '@sofie-package-manager/api'
 
 /**
  * Copies a file from one of the sources and into the target PackageContainer
@@ -111,7 +112,7 @@ export const JsonDataCopy: ExpectationWindowsHandler = {
 		if (!isJsonDataCopy(exp)) throw new Error(`Wrong exp.type: "${exp.type}"`)
 		// Copies the file from Source to Target
 
-		const startTime = Date.now()
+		const timer = startTimer()
 
 		const lookupSource = await lookupCopySources(worker, exp)
 		if (!lookupSource.ready) throw new Error(`Can't start working due to source: ${lookupSource.reason.tech}`)
@@ -180,7 +181,7 @@ export const JsonDataCopy: ExpectationWindowsHandler = {
 							await targetHandle.finalizePackage(fileOperation)
 							// await targetHandle.updateMetadata()
 
-							const duration = Date.now() - startTime
+							const duration = timer.get()
 							workInProgress._reportComplete(
 								actualSourceVersionHash,
 								{

shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/lib/file.ts

@@ -24,6 +24,7 @@ import { CancelablePromise } from '../../../../lib/cancelablePromise'
 import { PackageReadStream, PutPackageHandler } from '../../../../accessorHandlers/genericHandle'
 import { diff } from 'deep-diff'
 import { quantelFileflowCopy } from '../../lib/quantelFileflow'
+import { startTimer } from '@sofie-package-manager/api'
 
 export async function isFileReadyToStartWorkingOn(
 	worker: GenericWorker,
@@ -136,7 +137,7 @@ export async function doFileCopyExpectation(
 	if (!lookupSource.ready) throw new Error(`Can't start working due to source: ${lookupSource.reason.tech}`)
 	if (!lookupTarget.ready) throw new Error(`Can't start working due to target: ${lookupTarget.reason.tech}`)
 
-	const startTime = Date.now()
+	const timer = startTimer()
 
 	const actualSourceVersion = await lookupSource.handle.getPackageActualVersion()
 	const actualSourceVersionHash = hashObj(actualSourceVersion)
@@ -197,7 +198,7 @@ export async function doFileCopyExpectation(
 			await targetHandle.finalizePackage(fileOperation)
 			await targetHandle.updateMetadata(actualSourceUVersion)
 
-			const duration = Date.now() - startTime
+			const duration = timer.get()
 			workInProgress._reportComplete(
 				actualSourceVersionHash,
 				{
@@ -295,7 +296,7 @@ export async function doFileCopyExpectation(
 						await targetHandle.finalizePackage(fileOperation)
 						await targetHandle.updateMetadata(actualSourceUVersion)
 
-						const duration = Date.now() - startTime
+						const duration = timer.get()
 						workInProgress._reportComplete(
 							actualSourceVersionHash,
 							{
@@ -390,7 +391,7 @@ export async function doFileCopyExpectation(
 			await targetHandle.finalizePackage(fileOperation)
 			await targetHandle.updateMetadata(actualSourceUVersion)
 
-			const duration = Date.now() - startTime
+			const duration = timer.get()
 			workInProgress._reportComplete(
 				actualSourceVersionHash,
 				{

shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/mediaFilePreview.ts

@@ -28,6 +28,7 @@ import {
 } from './lib'
 import { FFMpegProcess, spawnFFMpeg } from './lib/ffmpeg'
 import { WindowsWorker } from '../windowsWorker'
+import { startTimer } from '@sofie-package-manager/api'
 
 /**
  * Generates a low-res preview video of a source video file, and stores the resulting file into the target PackageContainer
@@ -142,7 +143,7 @@ export const MediaFilePreview: ExpectationWindowsHandler = {
 		if (!isMediaFilePreview(exp)) throw new Error(`Wrong exp.type: "${exp.type}"`)
 		// Copies the file from Source to Target
 
-		const startTime = Date.now()
+		const timer = startTimer()
 
 		const lookupSource = await lookupPreviewSources(worker, exp)
 		if (!lookupSource.ready) throw new Error(`Can't start working due to source: ${lookupSource.reason.tech}`)
@@ -235,7 +236,7 @@ export const MediaFilePreview: ExpectationWindowsHandler = {
 						await targetHandle.finalizePackage(fileOperation)
 						await targetHandle.updateMetadata(metadata)
 
-						const duration = Date.now() - startTime
+						const duration = timer.get()
 						workInProgress._reportComplete(
 							actualSourceVersionHash,
 							{

shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/mediaFileThumbnail.ts

@@ -29,6 +29,7 @@ import {
 } from './lib'
 import { FFMpegProcess, spawnFFMpeg } from './lib/ffmpeg'
 import { WindowsWorker } from '../windowsWorker'
+import { startTimer } from '@sofie-package-manager/api'
 
 /**
  * Generates a thumbnail image from a source video file, and stores the resulting file into the target PackageContainer
@@ -139,7 +140,7 @@ export const MediaFileThumbnail: ExpectationWindowsHandler = {
 		if (!isMediaFileThumbnail(exp)) throw new Error(`Wrong exp.type: "${exp.type}"`)
 		// Create a thumbnail from the source media file
 
-		const startTime = Date.now()
+		const timer = startTimer()
 
 		const lookupSource = await lookupThumbnailSources(worker, exp)
 		if (!lookupSource.ready) throw new Error(`Can't start working due to source: ${lookupSource.reason.tech}`)
@@ -236,7 +237,7 @@ export const MediaFileThumbnail: ExpectationWindowsHandler = {
 						await targetHandle.finalizePackage(fileOperation)
 						await targetHandle.updateMetadata(metadata)
 
-						const duration = Date.now() - startTime
+						const duration = timer.get()
 						workInProgress._reportComplete(
 							sourceVersionHash,
 							{

shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/packageDeepScan.ts

@@ -26,6 +26,7 @@ import {
 	scanWithFFProbe,
 } from './lib/scan'
 import { WindowsWorker } from '../windowsWorker'
+import { startTimer } from '@sofie-package-manager/api'
 
 /**
  * Performs a "deep scan" of the source package and saves the result file into the target PackageContainer (a Sofie Core collection)
@@ -126,7 +127,7 @@ export const PackageDeepScan: ExpectationWindowsHandler = {
 	workOnExpectation: async (exp: Expectation.Any, worker: GenericWorker): Promise<IWorkInProgress> => {
 		if (!isPackageDeepScan(exp)) throw new Error(`Wrong exp.type: "${exp.type}"`)
 		// Scan the source media file and upload the results to Core
-		const startTime = Date.now()
+		const timer = startTimer()
 
 		const lookupSource = await lookupDeepScanSources(worker, exp)
 		if (!lookupSource.ready) throw new Error(`Can't start working due to source: ${lookupSource.reason.tech}`)
@@ -215,7 +216,7 @@ export const PackageDeepScan: ExpectationWindowsHandler = {
 
 			await targetHandle.finalizePackage(scanOperation)
 
-			const duration = Date.now() - startTime
+			const duration = timer.get()
 			workInProgress._reportComplete(
 				sourceVersionHash,
 				{

shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/packageLoudnessScan.ts

@@ -25,6 +25,7 @@ import {
 } from './lib/scan'
 import { WindowsWorker } from '../windowsWorker'
 import { LoudnessScanResult, PackageInfoType } from './lib/coreApi'
+import { startTimer } from '@sofie-package-manager/api'
 
 /**
  * Performs a "deep scan" of the source package and saves the result file into the target PackageContainer (a Sofie Core collection)
@@ -125,7 +126,7 @@ export const PackageLoudnessScan: ExpectationWindowsHandler = {
 	workOnExpectation: async (exp: Expectation.Any, worker: GenericWorker): Promise<IWorkInProgress> => {
 		if (!isPackageLoudnessScan(exp)) throw new Error(`Wrong exp.type: "${exp.type}"`)
 		// Scan the source media file and upload the results to Core
-		const startTime = Date.now()
+		const timer = startTimer()
 
 		const lookupSource = await lookupLoudnessSources(worker, exp)
 		if (!lookupSource.ready) throw new Error(`Can't start working due to source: ${lookupSource.reason.tech}`)
@@ -190,7 +191,7 @@ export const PackageLoudnessScan: ExpectationWindowsHandler = {
 			)
 			await targetHandle.finalizePackage(scanOperation)
 
-			const duration = Date.now() - startTime
+			const duration = timer.get()
 			workInProgress._reportComplete(
 				sourceVersionHash,
 				{

shared/packages/worker/src/worker/workers/windowsWorker/expectationHandlers/packageScan.ts

@@ -19,6 +19,7 @@ import { CancelablePromise } from '../../../lib/cancelablePromise'
 import { isAnFFMpegSupportedSourceAccessor, isAnFFMpegSupportedSourceAccessorHandle, scanWithFFProbe } from './lib/scan'
 import { WindowsWorker } from '../windowsWorker'
 import { PackageInfoType } from './lib/coreApi'
+import { startTimer } from '@sofie-package-manager/api'
 
 /**
  * Scans the source package and saves the result file into the target PackageContainer (a Sofie Core collection)
@@ -118,7 +119,7 @@ export const PackageScan: ExpectationWindowsHandler = {
 	workOnExpectation: async (exp: Expectation.Any, worker: GenericWorker): Promise<IWorkInProgress> => {
 		if (!isPackageScan(exp)) throw new Error(`Wrong exp.type: "${exp.type}"`)
 		// Scan the source package and upload the results to Core
-		const startTime = Date.now()
+		const timer = startTimer()
 
 		const lookupSource = await lookupScanSources(worker, exp)
 		if (!lookupSource.ready) throw new Error(`Can't start working due to source: ${lookupSource.reason.tech}`)
@@ -174,7 +175,7 @@ export const PackageScan: ExpectationWindowsHandler = {
 
 			await targetHandle.finalizePackage(scanOperation)
 
-			const duration = Date.now() - startTime
+			const duration = timer.get()
 			workInProgress._reportComplete(
 				sourceVersionHash,
 				{