[PM-22544] Add Performance measurement tools (#15475)

Adds logService.mark and logService.measure which are wrappers around performance.mark and performance.measure with extra debug logging for more visibility outside the performance tool.

libs/common/src/vault/services/cipher.service.ts

@@ -419,11 +419,13 @@ export class CipherService implements CipherServiceAbstraction {
     userId: UserId,
   ): Promise<[CipherView[], CipherView[]] | null> {
     if (await this.configService.getFeatureFlag(FeatureFlag.PM19941MigrateCipherDomainToSdk)) {
-      const decryptStartTime = new Date().getTime();
+      const decryptStartTime = performance.now();
       const decrypted = await this.decryptCiphersWithSdk(ciphers, userId);
-      this.logService.info(
-        `[CipherService] Decrypting ${decrypted.length} ciphers took ${new Date().getTime() - decryptStartTime}ms`,
-      );
+
+      this.logService.measure(decryptStartTime, "Vault", "CipherService", "decrypt complete", [
+        ["Items", ciphers.length],
+      ]);
+
       // With SDK, failed ciphers are not returned
       return [decrypted, []];
     }
@@ -442,7 +444,7 @@ export class CipherService implements CipherServiceAbstraction {
       },
       {} as Record<string, Cipher[]>,
     );
-    const decryptStartTime = new Date().getTime();
+    const decryptStartTime = performance.now();
     const allCipherViews = (
       await Promise.all(
         Object.entries(grouped).map(async ([orgId, groupedCiphers]) => {
@@ -462,9 +464,11 @@ export class CipherService implements CipherServiceAbstraction {
     )
       .flat()
       .sort(this.getLocaleSortingFunction());
-    this.logService.info(
-      `[CipherService] Decrypting ${allCipherViews.length} ciphers took ${new Date().getTime() - decryptStartTime}ms`,
-    );
+
+    this.logService.measure(decryptStartTime, "Vault", "CipherService", "decrypt complete", [
+      ["Items", ciphers.length],
+    ]);
+
     // Split ciphers into two arrays, one for successfully decrypted ciphers and one for ciphers that failed to decrypt
     return allCipherViews.reduce(
       (acc, c) => {

libs/common/src/vault/services/search.service.ts

@@ -129,12 +129,15 @@ export class SearchService implements SearchServiceAbstraction {
   }
 
   async isSearchable(userId: UserId, query: string): Promise<boolean> {
+    const time = performance.now();
     query = SearchService.normalizeSearchQuery(query);
     const index = await this.getIndexForSearch(userId);
     const notSearchable =
       query == null ||
       (index == null && query.length < this.searchableMinLength) ||
       (index != null && query.length < this.searchableMinLength && query.indexOf(">") !== 0);
+
+    this.logService.measure(time, "Vault", "SearchService", "isSearchable");
     return !notSearchable;
   }
 
@@ -147,7 +150,7 @@ export class SearchService implements SearchServiceAbstraction {
       return;
     }
 
-    const indexingStartTime = new Date().getTime();
+    const indexingStartTime = performance.now();
     await this.setIsIndexing(userId, true);
     await this.setIndexedEntityIdForSearch(userId, indexedEntityId as IndexedEntityId);
     const builder = new lunr.Builder();
@@ -188,11 +191,10 @@ export class SearchService implements SearchServiceAbstraction {
     await this.setIndexForSearch(userId, index.toJSON() as SerializedLunrIndex);
 
     await this.setIsIndexing(userId, false);
-    this.logService.info(
-      `[SearchService] Building search index of ${ciphers.length} ciphers took ${
-        new Date().getTime() - indexingStartTime
-      }ms`,
-    );
+
+    this.logService.measure(indexingStartTime, "Vault", "SearchService", "index complete", [
+      ["Items", ciphers.length],
+    ]);
   }
 
   async searchCiphers(

libs/key-management-ui/src/lock/components/lock.component.ts

@@ -577,6 +577,9 @@ export class LockComponent implements OnInit, OnDestroy {
       throw new Error("No active user.");
     }
 
+    // Add a mark to indicate that the user has unlocked their vault. A good starting point for measuring unlock performance.
+    this.logService.mark("Vault unlocked");
+
     await this.keyService.setUserKey(key, this.activeAccount.id);
 
     // Now that we have a decrypted user key in memory, we can check if we

libs/logging/src/console-log.service.ts

@@ -54,4 +54,43 @@ export class ConsoleLogService implements LogService {
         break;
     }
   }
+
+  measure(
+    start: DOMHighResTimeStamp,
+    trackGroup: string,
+    track: string,
+    name?: string,
+    properties?: [string, any][],
+  ): PerformanceMeasure {
+    const measureName = `[${track}]: ${name}`;
+
+    const measure = performance.measure(measureName, {
+      start: start,
+      detail: {
+        devtools: {
+          dataType: "track-entry",
+          track,
+          trackGroup,
+          properties,
+        },
+      },
+    });
+
+    this.info(`${measureName} took ${measure.duration}`, properties);
+    return measure;
+  }
+
+  mark(name: string): PerformanceMark {
+    const mark = performance.mark(name, {
+      detail: {
+        devtools: {
+          dataType: "marker",
+        },
+      },
+    });
+
+    this.info(mark.name, new Date().toISOString());
+
+    return mark;
+  }
 }

libs/logging/src/log.service.ts

@@ -6,4 +6,28 @@ export abstract class LogService {
   abstract warning(message?: any, ...optionalParams: any[]): void;
   abstract error(message?: any, ...optionalParams: any[]): void;
   abstract write(level: LogLevel, message?: any, ...optionalParams: any[]): void;
+
+  /**
+   * Helper wrapper around `performance.measure` to log a measurement. Should also debug-log the data.
+   *
+   * @param start Start time of the measurement.
+   * @param trackGroup A track-group for the measurement, should generally be the team owning the domain.
+   * @param track A track for the measurement, should generally be the class name.
+   * @param measureName A descriptive name for the measurement.
+   * @param properties Additional properties to include.
+   */
+  abstract measure(
+    start: DOMHighResTimeStamp,
+    trackGroup: string,
+    track: string,
+    measureName: string,
+    properties?: [string, any][],
+  ): PerformanceMeasure;
+
+  /**
+   * Helper wrapper around `performance.mark` to log a mark. Should also debug-log the data.
+   *
+   * @param name Name of the mark to create.
+   */
+  abstract mark(name: string): PerformanceMark;
 }