Timer Utility Class (#1054)

Refactor timing logic to use a new simple Timer utility class for
performance measurements across services.

Adds a timer for database import.

project/src/servers/SaveServer.ts

@@ -8,6 +8,7 @@ import { LocalisationService } from "@spt/services/LocalisationService";
 import { FileSystemSync } from "@spt/utils/FileSystemSync";
 import { HashUtil } from "@spt/utils/HashUtil";
 import { JsonUtil } from "@spt/utils/JsonUtil";
+import { Timer } from "@spt/utils/Timer";
 import { inject, injectAll, injectable } from "tsyringe";
 
 @injectable()
@@ -55,28 +56,26 @@ export class SaveServer {
         const files = this.fileSystemSync.getFiles(this.profileFilepath, false, ["json"]);
 
         // load profiles
-        const start = performance.now();
+        const timer = new Timer();
-        let loadTimeCount = 0;
         for (const file of files) {
             this.loadProfile(FileSystemSync.getFileName(file));
-            loadTimeCount += performance.now() - start;
         }
-
+        this.logger.debug(
-        this.logger.debug(`${files.length} Profiles took: ${loadTimeCount.toFixed(2)}ms to load.`);
+            `Loading ${files.length} profile${files.length > 1 ? "s" : ""} took ${timer.getTime("ms")}ms`,
+        );
     }
 
     /**
      * Save changes for each profile from memory into user/profiles json
      */
     public save(): void {
-        // Save every profile
+        const timer = new Timer();
-        let totalTime = 0;
         for (const sessionID in this.profiles) {
-            totalTime += this.saveProfile(sessionID);
+            this.saveProfile(sessionID);
         }
-
+        const profileCount = Object.keys(this.profiles).length;
         this.logger.debug(
-            `Saved ${Object.keys(this.profiles).length} profiles, took: ${totalTime.toFixed(2)}ms`,
+            `Saving ${profileCount} profile${profileCount > 1 ? "s" : ""} took ${timer.getTime("ms")}ms`,
             false,
         );
     }
@@ -171,9 +170,9 @@ export class SaveServer {
      * Save changes from in-memory profile to user/profiles json
      * Execute onBeforeSaveCallbacks callbacks prior to being saved to json
      * @param sessionID profile id (user/profiles/id.json)
-     * @returns time taken to save in MS
+     * @returns void
      */
-    public saveProfile(sessionID: string): number {
+    public saveProfile(sessionID: string): void {
         const filePath = `${this.profileFilepath}${sessionID}.json`;
 
         // Run pre-save callbacks before we save into json
@@ -187,7 +186,6 @@ export class SaveServer {
             }
         }
 
-        const start = performance.now();
         const jsonProfile = this.jsonUtil.serialize(
             this.profiles[sessionID],
             !this.configServer.getConfig<ICoreConfig>(ConfigTypes.CORE).features.compressProfile,
@@ -198,8 +196,6 @@ export class SaveServer {
             // save profile to disk
             this.fileSystemSync.write(filePath, jsonProfile);
         }
-
-        return Number(performance.now() - start);
     }
 
     /**

project/src/services/DatabaseService.ts

@@ -22,6 +22,7 @@ import type { ILogger } from "@spt/models/spt/utils/ILogger";
 import { DatabaseServer } from "@spt/servers/DatabaseServer";
 import { LocalisationService } from "@spt/services/LocalisationService";
 import { HashUtil } from "@spt/utils/HashUtil";
+import { Timer } from "@spt/utils/Timer";
 import { inject, injectable } from "tsyringe";
 
 @injectable()
@@ -333,8 +334,7 @@ export class DatabaseService {
      * Validates that the database doesn't contain invalid ID data
      */
     public validateDatabase(): void {
-        const start = performance.now();
+        const timer = new Timer();
-
         this.isDataValid =
             this.validateTable(this.getQuests(), "quest") &&
             this.validateTable(this.getTraders(), "trader") &&
@@ -345,8 +345,7 @@ export class DatabaseService {
             this.logger.error(this.localisationService.getText("database-invalid_data"));
         }
 
-        const validateTime = performance.now() - start;
+        this.logger.debug(`Database ID validation took ${timer.getTime("ms")}ms`);
-        this.logger.debug(`ID validation took: ${validateTime.toFixed(2)}ms`);
     }
 
     /**

project/src/services/ProfileFixerService.ts

@@ -25,6 +25,7 @@ import { LocalisationService } from "@spt/services/LocalisationService";
 import { HashUtil } from "@spt/utils/HashUtil";
 import { JsonUtil } from "@spt/utils/JsonUtil";
 import { TimeUtil } from "@spt/utils/TimeUtil";
+import { Timer } from "@spt/utils/Timer";
 import { Watermark } from "@spt/utils/Watermark";
 import type { ICloner } from "@spt/utils/cloners/ICloner";
 import { inject, injectable } from "tsyringe";
@@ -308,7 +309,7 @@ export class ProfileFixerService {
      * @param pmcProfile The profile to validate quest productions for
      */
     protected verifyQuestProductionUnlocks(pmcProfile: IPmcData): void {
-        const start = performance.now();
+        const timer = new Timer();
 
         const quests = this.databaseService.getQuests();
         const profileQuests = pmcProfile.Quests;
@@ -336,8 +337,7 @@ export class ProfileFixerService {
             }
         }
 
-        const validateTime = performance.now() - start;
+        this.logger.debug(`Quest production unlock validation took ${timer.getTime("ms")}ms`);
-        this.logger.debug(`Quest Production Unlock validation took: ${validateTime.toFixed(2)}ms`);
     }
 
     /**

project/src/utils/DatabaseImporter.ts

@@ -15,6 +15,7 @@ import { HashUtil } from "@spt/utils/HashUtil";
 import { ImporterUtil } from "@spt/utils/ImporterUtil";
 import { JsonUtil } from "@spt/utils/JsonUtil";
 import { inject, injectable } from "tsyringe";
+import { Timer } from "./Timer";
 
 @injectable()
 export class DatabaseImporter implements OnLoad {
@@ -81,6 +82,7 @@ export class DatabaseImporter implements OnLoad {
      */
     protected async hydrateDatabase(filepath: string): Promise<void> {
         this.logger.info(this.localisationService.getText("importing_database"));
+        const timer = new Timer();
 
         const dataToImport = await this.importerUtil.loadAsync<IDatabaseTables>(
             `${filepath}database/`,
@@ -90,7 +92,10 @@ export class DatabaseImporter implements OnLoad {
 
         const validation =
             this.valid === VaildationResult.FAILED || this.valid === VaildationResult.NOT_FOUND ? "." : "";
+
         this.logger.info(`${this.localisationService.getText("importing_database_finish")}${validation}`);
+        this.logger.debug(`Database import took ${timer.getTime("sec")}s`);
+
         this.databaseServer.setTables(dataToImport);
     }
 

project/src/utils/Timer.ts

@@ -0,0 +1,33 @@
+export class Timer {
+    private startTime: bigint = process.hrtime.bigint();
+
+    /**
+     * Resets the timer to its initial state.
+     */
+    public restart(): void {
+        this.startTime = process.hrtime.bigint();
+    }
+
+    /**
+     * Returns the elapsed time in the specified unit with up to four decimal places of precision for ms and sec.
+     *
+     * @param unit The desired unit for the elapsed time ("ns", "ms", "sec").
+     * @returns The elapsed time in the specified unit.
+     */
+    public getTime(unit: "ns" | "ms" | "sec"): number {
+        const elapsedTime = process.hrtime.bigint() - this.startTime;
+
+        switch (unit) {
+            case "ns":
+                return Number(elapsedTime);
+            case "ms": {
+                const ms = Number(elapsedTime) / 1_000_000;
+                return Number(ms.toFixed(3));
+            }
+            default: {
+                const sec = Number(elapsedTime) / 1_000_000_000;
+                return Number(sec.toFixed(4));
+            }
+        }
+    }
+}