From 1c04a388507b277f08c5afb180557c4d6098a92b Mon Sep 17 00:00:00 2001 From: tore-statsig <74584483+tore-statsig@users.noreply.github.com> Date: Tue, 8 Nov 2022 17:37:25 -0800 Subject: [PATCH] Add diagnostics for initialize time (#217) * Add diagnostics for initialize time * update test * diagnostics framework * update schema * feedback --- src/StatsigClient.ts | 42 ++++++++++++++- src/StatsigLogger.ts | 9 ++++ src/StatsigNetwork.ts | 31 +++++++++++ src/StatsigSDKOptions.ts | 7 +++ src/__tests__/AsyncInitVsUpdate.test.ts | 12 +++-- src/__tests__/LayerExposure.test.ts | 38 +++++++++---- src/__tests__/Logger.test.ts | 71 ++++++++++++++++++++++++- src/__tests__/StatsigSDKOptions.test.ts | 2 +- src/__tests__/StatsigSinceTime.test.ts | 2 + src/__tests__/index.test.ts | 18 ++++--- src/utils/Diagnostics.ts | 53 ++++++++++++++++++ src/utils/Timing.ts | 10 ++++ 12 files changed, 271 insertions(+), 24 deletions(-) create mode 100644 src/utils/Diagnostics.ts create mode 100644 src/utils/Timing.ts diff --git a/src/StatsigClient.ts b/src/StatsigClient.ts index ca03e65..feb56df 100644 --- a/src/StatsigClient.ts +++ b/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 = {}; + 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 { 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): Promise => { 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(() => { diff --git a/src/StatsigLogger.ts b/src/StatsigLogger.ts index ef1fd07..31b2acf 100644 --- a/src/StatsigLogger.ts +++ b/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; diff --git a/src/StatsigNetwork.ts b/src/StatsigNetwork.ts index 8913cb1..ebc2bde 100644 --- a/src/StatsigNetwork.ts +++ b/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) => Promise, rejectCallback: (e: Error) => void, + diagnostics?: Diagnostics, prefetchUsers?: Record, ): Promise { const input = { @@ -66,6 +71,7 @@ export default class StatsigNetwork { input, resolveCallback, rejectCallback, + diagnostics, timeout, // timeout for early returns 3, // retries ); @@ -76,10 +82,18 @@ export default class StatsigNetwork { body: object, resolveCallback: (json: Record) => Promise, rejectCallback: (e: Error) => void, + diagnostics?: Diagnostics, timeout: number = 0, retries: number = 0, backoff: number = 1000, ): Promise { + if (endpointName === StatsigEndpoint.Initialize) { + diagnostics?.mark( + DiagnosticsKey.INITIALIZE, + DiagnosticsEvent.START, + 'network_request', + ); + } const fetchPromise = this.postToEndpoint( endpointName, body, @@ -87,6 +101,14 @@ export default class StatsigNetwork { 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 */ }) .catch((e) => { + if (endpointName === StatsigEndpoint.Initialize) { + diagnostics?.mark( + DiagnosticsKey.INITIALIZE, + DiagnosticsEvent.END, + 'network_request', + false, + ); + } + if (typeof rejectCallback === 'function') { rejectCallback(e); } diff --git a/src/StatsigSDKOptions.ts b/src/StatsigSDKOptions.ts index 20275c4..bf2e8ec 100644 --- a/src/StatsigSDKOptions.ts +++ b/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, diff --git a/src/__tests__/AsyncInitVsUpdate.test.ts b/src/__tests__/AsyncInitVsUpdate.test.ts index 0862395..2aa0aad 100644 --- a/src/__tests__/AsyncInitVsUpdate.test.ts +++ b/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(); diff --git a/src/__tests__/LayerExposure.test.ts b/src/__tests__/LayerExposure.test.ts index cfbd606..0510e03 100644 --- a/src/__tests__/LayerExposure.test.ts +++ b/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: 'dan@loomb.io', - }); + await Statsig.initialize( + 'client-key', + { + userID: 'dloomb', + email: 'dan@loomb.io', + }, + { + disableDiagnosticsLogging: true, + }, + ); let layer = Statsig.getLayer('layer') as unknown as Indexable; layer[method]('an_int', 0); diff --git a/src/__tests__/Logger.test.ts b/src/__tests__/Logger.test.ts index e9fc2d2..e6a4f0f 100644 --- a/src/__tests__/Logger.test.ts +++ b/src/__tests__/Logger.test.ts @@ -24,6 +24,7 @@ describe('Verify behavior of StatsigLogger', () => { } return Promise.resolve({ ok: true, + status: 200, text: () => Promise.resolve( JSON.stringify({ @@ -51,7 +52,11 @@ describe('Verify behavior of StatsigLogger', () => { test('Test constructor', () => { expect.assertions(8); - const client = new StatsigClient(sdkKey, { userID: 'user_key' }); + const client = new StatsigClient( + sdkKey, + { userID: 'user_key' }, + { disableDiagnosticsLogging: true }, + ); const logger = client.getLogger(); const spyOnFlush = jest.spyOn(logger, 'flush'); const spyOnLog = jest.spyOn(logger, 'log'); @@ -199,4 +204,68 @@ describe('Verify behavior of StatsigLogger', () => { expect(spy).toHaveBeenCalledWith(false); }); }); + + test('Test diagnostics', async () => { + expect.assertions(2); + const client = new StatsigClient( + sdkKey, + { userID: 'user_key' }, + { disableCurrentPageLogging: true }, + ); + const logger = client.getLogger(); + const spyOnLog = jest.spyOn(logger, 'log'); + await client.initializeAsync(); + + expect(spyOnLog).toHaveBeenCalledTimes(1); + const event = new LogEvent('statsig::diagnostics'); + event.setMetadata({ + context: 'initialize', + markers: [ + { + action: 'start', + key: 'overall', + step: null, + timestamp: expect.any(Number), + value: null, + }, + { + action: 'start', + key: 'initialize', + step: 'network_request', + timestamp: expect.any(Number), + value: null, + }, + { + action: 'end', + key: 'initialize', + step: 'network_request', + timestamp: expect.any(Number), + value: 200, + }, + { + action: 'start', + key: 'initialize', + step: 'process', + timestamp: expect.any(Number), + value: null, + }, + { + action: 'end', + key: 'initialize', + step: 'process', + timestamp: expect.any(Number), + value: null, + }, + { + action: 'end', + key: 'overall', + step: null, + timestamp: expect.any(Number), + value: null, + }, + ], + }); + event.setUser({ userID: 'user_key' }); + expect(spyOnLog).toHaveBeenCalledWith(event); + }); }); diff --git a/src/__tests__/StatsigSDKOptions.test.ts b/src/__tests__/StatsigSDKOptions.test.ts index 8188ded..c361d49 100644 --- a/src/__tests__/StatsigSDKOptions.test.ts +++ b/src/__tests__/StatsigSDKOptions.test.ts @@ -113,7 +113,7 @@ describe('Test Statsig options', () => { expect(typeof initTime).toEqual('number'); expect(initTime).toBeGreaterThanOrEqual(10); - expect(initTime).toBeLessThanOrEqual(100); + expect(initTime).toBeLessThanOrEqual(1000); expect(initSuccess).toEqual(false); expect(initMessage).toEqual( 'The initialization timeout of 10ms has been hit before the network request has completed.', diff --git a/src/__tests__/StatsigSinceTime.test.ts b/src/__tests__/StatsigSinceTime.test.ts index 6f5c373..1882bf7 100644 --- a/src/__tests__/StatsigSinceTime.test.ts +++ b/src/__tests__/StatsigSinceTime.test.ts @@ -87,6 +87,7 @@ describe('Verify behavior of StatsigClient with sinceTime', () => { expect.anything(), expect.anything(), expect.anything(), + expect.anything(), undefined, ); @@ -107,6 +108,7 @@ describe('Verify behavior of StatsigClient with sinceTime', () => { expect.anything(), expect.anything(), undefined, + undefined, ); }); }); diff --git a/src/__tests__/index.test.ts b/src/__tests__/index.test.ts index 89db64c..6911b7c 100644 --- a/src/__tests__/index.test.ts +++ b/src/__tests__/index.test.ts @@ -449,12 +449,18 @@ describe('Verify behavior of top level index functions', () => { test('shutdown does flush logs and they are correct', async () => { expect.assertions(8); - await statsig.initialize('client-key', { - userID: '12345', - country: 'US', - custom: { key: 'value' }, - privateAttributes: { private: 'value' }, - }); + await statsig.initialize( + 'client-key', + { + userID: '12345', + country: 'US', + custom: { key: 'value' }, + privateAttributes: { private: 'value' }, + }, + { + disableDiagnosticsLogging: true, + }, + ); expect(statsig.checkGate('test_gate')).toEqual(true); const config = statsig.getConfig('test_config'); expect(config?.value).toStrictEqual({ diff --git a/src/utils/Diagnostics.ts b/src/utils/Diagnostics.ts new file mode 100644 index 0000000..36b3362 --- /dev/null +++ b/src/utils/Diagnostics.ts @@ -0,0 +1,53 @@ +import { now } from './Timing'; + +export enum DiagnosticsEvent { + START = 'start', + END = 'end', +} + +export enum DiagnosticsKey { + OVERALL = 'overall', + INITIALIZE = 'initialize', +} + +export type DiagnosticsMarker = Record< + string, + string | number | boolean | null | undefined +>; + +export type DiagnosticsMarkers = { + context: string; + markers: DiagnosticsMarker[]; +}; + +export default class Diagnostics { + private markers: DiagnosticsMarker[]; + private context: string; + + public constructor(context: string) { + this.context = context; + this.markers = []; + } + + public getMarkers(): DiagnosticsMarkers { + return { + context: this.context, + markers: this.markers, + }; + } + + public mark( + key: DiagnosticsKey, + action: DiagnosticsEvent, + step: string | null = null, + value: string | number | boolean | null = null, + ): void { + this.markers.push({ + key, + step, + action, + value, + timestamp: now(), + }); + } +} diff --git a/src/utils/Timing.ts b/src/utils/Timing.ts new file mode 100644 index 0000000..3b1d182 --- /dev/null +++ b/src/utils/Timing.ts @@ -0,0 +1,10 @@ +export function now(): number { + if (typeof performance === 'undefined' || !performance) { + return Date.now(); + } + return performance.now() | 0; +} + +export function difference(time: number): number { + return now() - time; +}