Add diagnostics for initialize time (#217)

* Add diagnostics for initialize time

* update test

* diagnostics framework

* update schema

* feedback

src/StatsigClient.ts

@@ -26,6 +26,11 @@ import { getUserCacheKey } from './utils/Hashing';
 import StatsigAsyncStorage from './utils/StatsigAsyncStorage';
 import type { AsyncStorage } from './utils/StatsigAsyncStorage';
 import StatsigLocalStorage from './utils/StatsigLocalStorage';
+import { difference, now } from './utils/Timing';
+import Diagnostics, {
+  DiagnosticsEvent,
+  DiagnosticsKey,
+} from './utils/Diagnostics';
 
 const MAX_VALUE_SIZE = 64;
 const MAX_OBJ_SIZE = 2048;
@@ -114,6 +119,8 @@ export default class StatsigClient implements IHasStatsigInternal, IStatsig {
   private optionalLoggingSetup: boolean = false;
   private prefetchedUsersByCacheKey: Record<string, StatsigUser> = {};
 
+  private initializeDiagnostics: Diagnostics;
+
   private errorBoundary: ErrorBoundary;
   public getErrorBoundary(): ErrorBoundary {
     return this.errorBoundary;
@@ -182,6 +189,7 @@ export default class StatsigClient implements IHasStatsigInternal, IStatsig {
     this.sdkKey = sdkKey;
     this.options = new StatsigSDKOptions(options);
     StatsigLocalStorage.disabled = this.options.getDisableLocalStorage();
+    this.initializeDiagnostics = new Diagnostics('initialize');
     this.identity = new StatsigIdentity(
       this.normalizeUser(user ?? null),
       this.options.getOverrideStableID(),
@@ -231,6 +239,10 @@ export default class StatsigClient implements IHasStatsigInternal, IStatsig {
         if (this.ready) {
           return Promise.resolve();
         }
+        this.initializeDiagnostics.mark(
+          DiagnosticsKey.OVERALL,
+          DiagnosticsEvent.START,
+        );
         this.initCalled = true;
         if (StatsigAsyncStorage.asyncStorage) {
           await this.identity.initAsync();
@@ -263,14 +275,23 @@ export default class StatsigClient implements IHasStatsigInternal, IStatsig {
           }
         };
 
+        const user = this.identity.getUser();
         this.pendingInitPromise = this.fetchAndSaveValues(
-          this.identity.getUser(),
+          user,
           this.options.getPrefetchUsers(),
           completionCallback,
+          this.initializeDiagnostics,
         ).finally(async () => {
           this.pendingInitPromise = null;
           this.ready = true;
           this.logger.sendSavedRequests();
+          this.initializeDiagnostics.mark(
+            DiagnosticsKey.OVERALL,
+            DiagnosticsEvent.END,
+          );
+          if (!this.options.getDisableDiagnosticsLogging()) {
+            this.logger.logDiagnostics(user, this.initializeDiagnostics);
+          }
         });
 
         this.handleOptionalLogging();
@@ -680,12 +701,17 @@ export default class StatsigClient implements IHasStatsigInternal, IStatsig {
   }
 
   private handleOptionalLogging(): void {
-    if (typeof window === 'undefined' || !window || !window.addEventListener) {
+    if (typeof window === 'undefined' || !window) {
       return;
     }
     if (this.optionalLoggingSetup) {
       return;
     }
+
+    if (!window.addEventListener) {
+      return;
+    }
+
     const user = this.identity.getUser();
     if (!this.options.getDisableErrorLogging()) {
       window.addEventListener('error', (e) => {
@@ -817,6 +843,7 @@ export default class StatsigClient implements IHasStatsigInternal, IStatsig {
     completionCallback:
       | ((success: boolean, message: string | null) => void)
       | null = null,
+    diagnostics?: Diagnostics,
   ): Promise<void> {
     if (prefetchUsers.length > 5) {
       console.warn('Cannot prefetch more than 5 users.');
@@ -839,6 +866,11 @@ export default class StatsigClient implements IHasStatsigInternal, IStatsig {
         this.options.getInitTimeoutMs(),
         async (json: Record<string, any>): Promise<void> => {
           return this.errorBoundary.swallow('fetchAndSaveValues', async () => {
+            diagnostics?.mark(
+              DiagnosticsKey.INITIALIZE,
+              DiagnosticsEvent.START,
+              'process',
+            );
             if (json?.has_updates) {
               await this.store.save(user, json);
             }
@@ -847,9 +879,15 @@ export default class StatsigClient implements IHasStatsigInternal, IStatsig {
               ...this.prefetchedUsersByCacheKey,
               ...keyedPrefetchUsers,
             };
+            diagnostics?.mark(
+              DiagnosticsKey.INITIALIZE,
+              DiagnosticsEvent.END,
+              'process',
+            );
           });
         },
         (e: Error) => {},
+        prefetchUsers.length === 0 ? diagnostics : undefined,
         prefetchUsers.length > 0 ? keyedPrefetchUsers : undefined,
       )
       .then(() => {

src/StatsigLogger.ts

@@ -4,6 +4,7 @@ import { StatsigEndpoint } from './StatsigNetwork';
 import { EvaluationDetails } from './StatsigStore';
 import { StatsigUser } from './StatsigUser';
 import { STATSIG_LOCAL_STORAGE_LOGGING_REQUEST_KEY } from './utils/Constants';
+import Diagnostics from './utils/Diagnostics';
 import StatsigAsyncStorage from './utils/StatsigAsyncStorage';
 import StatsigLocalStorage from './utils/StatsigLocalStorage';
 
@@ -17,6 +18,7 @@ const APP_METRICS_PAGE_LOAD_EVENT =
   INTERNAL_EVENT_PREFIX + 'app_metrics::page_load_time';
 const APP_METRICS_DOM_INTERACTIVE_EVENT =
   INTERNAL_EVENT_PREFIX + 'app_metrics::dom_interactive_time';
+const DIAGNOSTICS_EVENT = INTERNAL_EVENT_PREFIX + 'diagnostics';
 
 type FailedLogEventBody = {
   events: object[];
@@ -245,6 +247,13 @@ export default class StatsigLogger {
     this.loggedErrors.add(trimmedMessage);
   }
 
+  public logDiagnostics(user: StatsigUser | null, diagnostics: Diagnostics) {
+    const latencyEvent = new LogEvent(DIAGNOSTICS_EVENT);
+    latencyEvent.setUser(user);
+    latencyEvent.setMetadata(diagnostics.getMarkers());
+    this.log(latencyEvent);
+  }
+
   public logAppMetrics(user: StatsigUser | null) {
     if (typeof window?.performance?.getEntriesByType !== 'function') {
       return;

src/StatsigNetwork.ts

@@ -1,6 +1,10 @@
 import { IHasStatsigInternal } from './StatsigClient';
 import StatsigRuntime from './StatsigRuntime';
 import { StatsigUser } from './StatsigUser';
+import Diagnostics, {
+  DiagnosticsEvent,
+  DiagnosticsKey,
+} from './utils/Diagnostics';
 
 export enum StatsigEndpoint {
   Initialize = 'initialize',
@@ -52,6 +56,7 @@ export default class StatsigNetwork {
     timeout: number,
     resolveCallback: (json: Record<string, any>) => Promise<void>,
     rejectCallback: (e: Error) => void,
+    diagnostics?: Diagnostics,
     prefetchUsers?: Record<string, StatsigUser>,
   ): Promise<void> {
     const input = {
@@ -66,6 +71,7 @@ export default class StatsigNetwork {
       input,
       resolveCallback,
       rejectCallback,
+      diagnostics,
       timeout, // timeout for early returns
       3, // retries
     );
@@ -76,17 +82,33 @@ export default class StatsigNetwork {
     body: object,
     resolveCallback: (json: Record<string, any>) => Promise<void>,
     rejectCallback: (e: Error) => void,
+    diagnostics?: Diagnostics,
     timeout: number = 0,
     retries: number = 0,
     backoff: number = 1000,
   ): Promise<void> {
+    if (endpointName === StatsigEndpoint.Initialize) {
+      diagnostics?.mark(
+        DiagnosticsKey.INITIALIZE,
+        DiagnosticsEvent.START,
+        'network_request',
+      );
+    }
     const fetchPromise = this.postToEndpoint(
       endpointName,
       body,
       retries,
       backoff,
     )
       .then((res) => {
+        if (endpointName === StatsigEndpoint.Initialize) {
+          diagnostics?.mark(
+            DiagnosticsKey.INITIALIZE,
+            DiagnosticsEvent.END,
+            'network_request',
+            res.status,
+          );
+        }
         if (!res.ok) {
           return Promise.reject(
             new Error(
@@ -132,6 +154,15 @@ export default class StatsigNetwork {
         /* return Promise<void> */
       })
       .catch((e) => {
+        if (endpointName === StatsigEndpoint.Initialize) {
+          diagnostics?.mark(
+            DiagnosticsKey.INITIALIZE,
+            DiagnosticsEvent.END,
+            'network_request',
+            false,
+          );
+        }
+
         if (typeof rejectCallback === 'function') {
           rejectCallback(e);
         }

src/StatsigSDKOptions.ts

@@ -31,6 +31,7 @@ export type StatsigOptions = {
   prefetchUsers?: StatsigUser[];
   disableLocalStorage?: boolean;
   initCompletionCallback?: InitCompletionCallback | null;
+  disableDiagnosticsLogging?: boolean;
 };
 
 type BoundedNumberInput = {
@@ -56,6 +57,7 @@ export default class StatsigSDKOptions {
   private prefetchUsers: StatsigUser[];
   private disableLocalStorage: boolean;
   private initCompletionCallback: InitCompletionCallback | null;
+  private disableDiagnosticsLogging: boolean;
 
   constructor(options?: StatsigOptions | null) {
     if (options == null) {
@@ -100,6 +102,7 @@ export default class StatsigSDKOptions {
     this.prefetchUsers = options.prefetchUsers ?? [];
     this.disableLocalStorage = options.disableLocalStorage ?? false;
     this.initCompletionCallback = options.initCompletionCallback ?? null;
+    this.disableDiagnosticsLogging = options.disableDiagnosticsLogging ?? false;
   }
 
   getApi(): string {
@@ -162,6 +165,10 @@ export default class StatsigSDKOptions {
     return this.initCompletionCallback;
   }
 
+  getDisableDiagnosticsLogging(): boolean {
+    return this.disableDiagnosticsLogging;
+  }
+
   private normalizeNumberInput(
     input: number | undefined,
     bounds: BoundedNumberInput,

src/__tests__/AsyncInitVsUpdate.test.ts

@@ -92,10 +92,14 @@ describe('Race conditions between initializeAsync and updateUser', () => {
 
   it('does not overwrite user values when unawaited response return', async () => {
     Statsig.encodeIntializeCall = false;
-    const client = new StatsigClient('client-key', {
-      userID: 'user-a',
-      customIDs: { workID: 'employee-a' },
-    });
+    const client = new StatsigClient(
+      'client-key',
+      {
+        userID: 'user-a',
+        customIDs: { workID: 'employee-a' },
+      },
+      { disableDiagnosticsLogging: true },
+    );
 
     // Call both without awaiting either
     client.initializeAsync();

src/__tests__/LayerExposure.test.ts

@@ -52,7 +52,9 @@ describe('Layer Exposure Logging', () => {
       value: { an_int: 99 },
     };
 
-    await Statsig.initialize('client-key');
+    await Statsig.initialize('client-key', null, {
+      disableDiagnosticsLogging: true,
+    });
 
     let layer = Statsig.getLayer('layer') as unknown as Indexable;
     layer.get('an_int', '');
@@ -65,7 +67,9 @@ describe('Layer Exposure Logging', () => {
 
   describe.each([['getValue'], ['get']])('with method "%s"', (method) => {
     it('does not log a non-existent key', async () => {
-      await Statsig.initialize('client-key');
+      await Statsig.initialize('client-key', null, {
+        disableDiagnosticsLogging: true,
+      });
 
       let layer = Statsig.getLayer('layer') as unknown as Indexable;
       layer[method]('an_int', 0);
@@ -88,7 +92,9 @@ describe('Layer Exposure Logging', () => {
         explicit_parameters: [],
       };
 
-      await Statsig.initialize('client-key');
+      await Statsig.initialize('client-key', null, {
+        disableDiagnosticsLogging: true,
+      });
 
       let layer = Statsig.getLayer('layer') as unknown as Indexable;
       layer[method]('an_int', 0);
@@ -124,7 +130,9 @@ describe('Layer Exposure Logging', () => {
         explicit_parameters: ['an_int'],
       };
 
-      await Statsig.initialize('client-key');
+      await Statsig.initialize('client-key', null, {
+        disableDiagnosticsLogging: true,
+      });
 
       let layer = Statsig.getLayer('layer') as unknown as Indexable;
       layer[method]('an_int', 0);
@@ -177,7 +185,9 @@ describe('Layer Exposure Logging', () => {
         },
       };
 
-      await Statsig.initialize('client-key');
+      await Statsig.initialize('client-key', null, {
+        disableDiagnosticsLogging: true,
+      });
 
       let layer = Statsig.getLayer('layer') as unknown as Indexable;
       layer[method]('a_bool', false);
@@ -215,7 +225,9 @@ describe('Layer Exposure Logging', () => {
         },
       };
 
-      await Statsig.initialize('client-key');
+      await Statsig.initialize('client-key', null, {
+        disableDiagnosticsLogging: true,
+      });
 
       let layer = Statsig.getLayer('layer') as unknown as Indexable;
       Statsig.shutdown();
@@ -232,10 +244,16 @@ describe('Layer Exposure Logging', () => {
         value: { an_int: 99 },
       };
 
-      await Statsig.initialize('client-key', {
-        userID: 'dloomb',
-        email: '[email protected]',
-      });
+      await Statsig.initialize(
+        'client-key',
+        {
+          userID: 'dloomb',
+          email: '[email protected]',
+        },
+        {
+          disableDiagnosticsLogging: true,
+        },
+      );
 
       let layer = Statsig.getLayer('layer') as unknown as Indexable;
       layer[method]('an_int', 0);