From f6d346586e4687522d56a80e6ad1c8c856da4cb5 Mon Sep 17 00:00:00 2001 From: Bastien Caudan <1331991+bcaudan@users.noreply.github.com> Date: Thu, 15 Feb 2024 09:43:40 +0100 Subject: [PATCH] =?UTF-8?q?=E2=9A=97=EF=B8=8F[RUM-2889]=20custom=20vitals?= =?UTF-8?q?=20improvements=20(#2606)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * 🐛 Fix multiple vital creation with multiple stop calls * ✨ Add event limiter for vitals * ✨ Allow to pass customer context to start/stop API * ✨ Allow to pass startTime/stopTime --- packages/core/src/tools/utils/timeUtils.ts | 4 + .../rum-core/src/boot/rumPublicApi.spec.ts | 70 ++++++- packages/rum-core/src/boot/rumPublicApi.ts | 48 +++-- packages/rum-core/src/domain/assembly.spec.ts | 190 +++++++----------- packages/rum-core/src/domain/assembly.ts | 5 + .../src/domain/vital/vitalCollection.spec.ts | 47 +++++ .../src/domain/vital/vitalCollection.ts | 10 +- 7 files changed, 241 insertions(+), 133 deletions(-) diff --git a/packages/core/src/tools/utils/timeUtils.ts b/packages/core/src/tools/utils/timeUtils.ts index c8c5991cff..c2c475ace0 100644 --- a/packages/core/src/tools/utils/timeUtils.ts +++ b/packages/core/src/tools/utils/timeUtils.ts @@ -16,6 +16,10 @@ export function relativeToClocks(relative: RelativeTime) { return { relative, timeStamp: getCorrectedTimeStamp(relative) } } +export function timeStampToClocks(timeStamp: TimeStamp) { + return { relative: getRelativeTime(timeStamp), timeStamp } +} + function getCorrectedTimeStamp(relativeTime: RelativeTime) { const correctedOrigin = (dateNow() - performance.now()) as TimeStamp // apply correction only for positive drift diff --git a/packages/rum-core/src/boot/rumPublicApi.spec.ts b/packages/rum-core/src/boot/rumPublicApi.spec.ts index 03bc85779b..79c4229588 100644 --- a/packages/rum-core/src/boot/rumPublicApi.spec.ts +++ b/packages/rum-core/src/boot/rumPublicApi.spec.ts @@ -1,5 +1,7 @@ -import type { RelativeTime, Context, DeflateWorker, CustomerDataTrackerManager } from '@datadog/browser-core' +import type { RelativeTime, Context, DeflateWorker, CustomerDataTrackerManager, TimeStamp } from '@datadog/browser-core' import { + timeStampToClocks, + clocksNow, addExperimentalFeatures, ExperimentalFeature, resetExperimentalFeatures, @@ -722,6 +724,10 @@ describe('rum public api', () => { }) describe('startDurationVital', () => { + beforeEach(() => { + setup().withFakeClock().build() + }) + afterEach(() => { resetExperimentalFeatures() }) @@ -744,12 +750,41 @@ describe('rum public api', () => { ) rumPublicApi.init(DEFAULT_INIT_CONFIGURATION) // eslint-disable-next-line @typescript-eslint/no-unsafe-call - ;(rumPublicApi as any).startDurationVital('foo') - expect(startDurationVitalSpy).toHaveBeenCalledWith({ name: 'foo', startClocks: jasmine.any(Object) }) + ;(rumPublicApi as any).startDurationVital('foo', { context: { foo: 'bar' } }) + expect(startDurationVitalSpy).toHaveBeenCalledWith({ + name: 'foo', + startClocks: clocksNow(), + context: { foo: 'bar' }, + }) + }) + + it('should call startDurationVital with provided startTime when ff is enabled', () => { + addExperimentalFeatures([ExperimentalFeature.CUSTOM_VITALS]) + const startDurationVitalSpy = jasmine.createSpy() + const rumPublicApi = makeRumPublicApi( + () => ({ + ...noopStartRum(), + startDurationVital: startDurationVitalSpy, + }), + noopRecorderApi + ) + const startTime = 1707755888000 as TimeStamp + rumPublicApi.init(DEFAULT_INIT_CONFIGURATION) + // eslint-disable-next-line @typescript-eslint/no-unsafe-call + ;(rumPublicApi as any).startDurationVital('foo', { startTime }) + expect(startDurationVitalSpy).toHaveBeenCalledWith({ + name: 'foo', + startClocks: timeStampToClocks(startTime), + context: undefined, + }) }) }) describe('stopDurationVital', () => { + beforeEach(() => { + setup().withFakeClock().build() + }) + afterEach(() => { resetExperimentalFeatures() }) @@ -772,8 +807,33 @@ describe('rum public api', () => { ) rumPublicApi.init(DEFAULT_INIT_CONFIGURATION) // eslint-disable-next-line @typescript-eslint/no-unsafe-call - ;(rumPublicApi as any).stopDurationVital('foo') - expect(stopDurationVitalSpy).toHaveBeenCalledWith({ name: 'foo', stopClocks: jasmine.any(Object) }) + ;(rumPublicApi as any).stopDurationVital('foo', { context: { foo: 'bar' } }) + expect(stopDurationVitalSpy).toHaveBeenCalledWith({ + name: 'foo', + stopClocks: clocksNow(), + context: { foo: 'bar' }, + }) + }) + + it('should call stopDurationVital with provided stopTime when ff is enabled', () => { + addExperimentalFeatures([ExperimentalFeature.CUSTOM_VITALS]) + const stopDurationVitalSpy = jasmine.createSpy() + const rumPublicApi = makeRumPublicApi( + () => ({ + ...noopStartRum(), + stopDurationVital: stopDurationVitalSpy, + }), + noopRecorderApi + ) + const stopTime = 1707755888000 as TimeStamp + rumPublicApi.init(DEFAULT_INIT_CONFIGURATION) + // eslint-disable-next-line @typescript-eslint/no-unsafe-call + ;(rumPublicApi as any).stopDurationVital('foo', { stopTime }) + expect(stopDurationVitalSpy).toHaveBeenCalledWith({ + name: 'foo', + stopClocks: timeStampToClocks(stopTime), + context: undefined, + }) }) }) diff --git a/packages/rum-core/src/boot/rumPublicApi.ts b/packages/rum-core/src/boot/rumPublicApi.ts index 8f50aa1ba1..e88333ecd3 100644 --- a/packages/rum-core/src/boot/rumPublicApi.ts +++ b/packages/rum-core/src/boot/rumPublicApi.ts @@ -9,6 +9,7 @@ import type { TrackingConsent, } from '@datadog/browser-core' import { + timeStampToClocks, isExperimentalFeatureEnabled, ExperimentalFeature, CustomerDataType, @@ -107,18 +108,41 @@ export function makeRumPublicApi(startRumImpl: StartRum, recorderApi: RecorderAp (initConfiguration, configuration, deflateWorker, initialViewOptions) => { if (isExperimentalFeatureEnabled(ExperimentalFeature.CUSTOM_VITALS)) { - ;(rumPublicApi as any).startDurationVital = monitor((name: string) => { - strategy.startDurationVital({ - name: sanitize(name)!, - startClocks: clocksNow(), - }) - }) - ;(rumPublicApi as any).stopDurationVital = monitor((name: string) => { - strategy.stopDurationVital({ - name: sanitize(name)!, - stopClocks: clocksNow(), - }) - }) + /** + * Start a custom duration vital + * stored in @vital.custom. + * + * @param name name of the custom vital + * @param options.context custom context attached to the vital + * @param options.startTime epoch timestamp of the start of the custom vital (if not set, will use current time) + */ + ;(rumPublicApi as any).startDurationVital = monitor( + (name: string, options?: { context?: object; startTime?: number }) => { + strategy.startDurationVital({ + name: sanitize(name)!, + startClocks: options?.startTime ? timeStampToClocks(options.startTime as TimeStamp) : clocksNow(), + context: sanitize(options?.context) as Context, + }) + } + ) + + /** + * Stop a custom duration vital + * stored in @vital.custom. + * + * @param name name of the custom vital + * @param options.context custom context attached to the vital + * @param options.stopTime epoch timestamp of the stop of the custom vital (if not set, will use current time) + */ + ;(rumPublicApi as any).stopDurationVital = monitor( + (name: string, options?: { context?: object; stopTime?: number }) => { + strategy.stopDurationVital({ + name: sanitize(name)!, + stopClocks: options?.stopTime ? timeStampToClocks(options.stopTime as TimeStamp) : clocksNow(), + context: sanitize(options?.context) as Context, + }) + } + ) } if (initConfiguration.storeContextsAcrossPages) { diff --git a/packages/rum-core/src/domain/assembly.spec.ts b/packages/rum-core/src/domain/assembly.spec.ts index 61e669976a..79b49529aa 100644 --- a/packages/rum-core/src/domain/assembly.spec.ts +++ b/packages/rum-core/src/domain/assembly.spec.ts @@ -1,4 +1,4 @@ -import type { ClocksState, RelativeTime } from '@datadog/browser-core' +import type { ClocksState, RelativeTime, TimeStamp } from '@datadog/browser-core' import { ErrorSource, ExperimentalFeature, ONE_MINUTE, display } from '@datadog/browser-core' import { initEventBridgeStub, @@ -18,7 +18,7 @@ import { cleanupCiVisibilityWindowValues, } from '../../test' import type { RumEventDomainContext } from '../domainContext.types' -import type { RawRumActionEvent, RawRumErrorEvent, RawRumEvent } from '../rawRumEvent.types' +import type { RawRumActionEvent, RawRumEvent } from '../rawRumEvent.types' import { RumEventType } from '../rawRumEvent.types' import type { RumActionEvent, RumErrorEvent, RumEvent, RumResourceEvent } from '../rumEvent.types' import { startRumAssembly } from './assembly' @@ -827,128 +827,90 @@ describe('rum assembly', () => { }) }) }) - - describe('error events limitation', () => { - it('stops sending error events when reaching the limit', () => { - const { lifeCycle } = setupBuilder.withConfiguration({ eventRateLimiterThreshold: 1 }).build() - notifyRawRumErrorEvent(lifeCycle, 'foo') - notifyRawRumErrorEvent(lifeCycle, 'bar') - - expect(serverRumEvents.length).toBe(1) - expect((serverRumEvents[0] as RumErrorEvent).error.message).toBe('foo') - expect(reportErrorSpy).toHaveBeenCalledTimes(1) - expect(reportErrorSpy.calls.argsFor(0)[0]).toEqual( - jasmine.objectContaining({ - message: 'Reached max number of errors by minute: 1', - source: ErrorSource.AGENT, + ;[ + { + eventType: RumEventType.ERROR, + message: 'Reached max number of errors by minute: 1', + }, + { + eventType: RumEventType.ACTION, + message: 'Reached max number of actions by minute: 1', + }, + { + eventType: RumEventType.VITAL, + message: 'Reached max number of vitals by minute: 1', + }, + ].forEach(({ eventType, message }) => { + describe(`${eventType} events limitation`, () => { + it(`stops sending ${eventType} events when reaching the limit`, () => { + const { lifeCycle } = setupBuilder.withConfiguration({ eventRateLimiterThreshold: 1 }).build() + notifyRawRumEvent(lifeCycle, { + rawRumEvent: createRawRumEvent(eventType, { date: 100 as TimeStamp }), }) - ) - }) - - it('does not take discarded errors into account', () => { - const { lifeCycle } = setupBuilder - .withConfiguration({ - eventRateLimiterThreshold: 1, - beforeSend: (event) => { - if (event.type === RumEventType.ERROR && (event as RumErrorEvent).error.message === 'discard me') { - return false - } - }, + notifyRawRumEvent(lifeCycle, { + rawRumEvent: createRawRumEvent(eventType, { date: 200 as TimeStamp }), }) - .build() - notifyRawRumErrorEvent(lifeCycle, 'discard me') - notifyRawRumErrorEvent(lifeCycle, 'discard me') - notifyRawRumErrorEvent(lifeCycle, 'discard me') - notifyRawRumErrorEvent(lifeCycle, 'foo') - expect(serverRumEvents.length).toBe(1) - expect((serverRumEvents[0] as RumErrorEvent).error.message).toBe('foo') - expect(reportErrorSpy).not.toHaveBeenCalled() - }) - - it('allows to send new errors after a minute', () => { - const { lifeCycle, clock } = setupBuilder - .withFakeClock() - .withConfiguration({ eventRateLimiterThreshold: 1 }) - .build() - notifyRawRumErrorEvent(lifeCycle, 'foo') - notifyRawRumErrorEvent(lifeCycle, 'bar') - clock.tick(ONE_MINUTE) - notifyRawRumErrorEvent(lifeCycle, 'baz') - - expect(serverRumEvents.length).toBe(2) - expect((serverRumEvents[0] as RumErrorEvent).error.message).toBe('foo') - expect((serverRumEvents[1] as RumErrorEvent).error.message).toBe('baz') - }) - function notifyRawRumErrorEvent(lifeCycle: LifeCycle, message: string) { - const rawRumEvent = createRawRumEvent(RumEventType.ERROR) as RawRumErrorEvent - rawRumEvent.error.message = message - notifyRawRumEvent(lifeCycle, { - rawRumEvent, + expect(serverRumEvents.length).toBe(1) + expect(serverRumEvents[0].date).toBe(100) + expect(reportErrorSpy).toHaveBeenCalledTimes(1) + expect(reportErrorSpy.calls.argsFor(0)[0]).toEqual( + jasmine.objectContaining({ + message, + source: ErrorSource.AGENT, + }) + ) }) - } - }) - - describe('action events limitation', () => { - it('stops sending action events when reaching the limit', () => { - const { lifeCycle } = setupBuilder.withConfiguration({ eventRateLimiterThreshold: 1 }).build() - notifyRumActionEvent(lifeCycle, 'foo') - notifyRumActionEvent(lifeCycle, 'bar') - - expect(serverRumEvents.length).toBe(1) - expect((serverRumEvents[0] as RumActionEvent).action.target?.name).toBe('foo') - expect(reportErrorSpy).toHaveBeenCalledTimes(1) - expect(reportErrorSpy.calls.argsFor(0)[0]).toEqual( - jasmine.objectContaining({ - message: 'Reached max number of actions by minute: 1', - source: ErrorSource.AGENT, + it(`does not take discarded ${eventType} events into account`, () => { + const { lifeCycle } = setupBuilder + .withConfiguration({ + eventRateLimiterThreshold: 1, + beforeSend: (event) => { + if (event.type === eventType && event.date === 100) { + return false + } + }, + }) + .build() + notifyRawRumEvent(lifeCycle, { + rawRumEvent: createRawRumEvent(eventType, { date: 100 as TimeStamp }), }) - ) - }) - - it('does not take discarded actions into account', () => { - const { lifeCycle } = setupBuilder - .withConfiguration({ - eventRateLimiterThreshold: 1, - beforeSend: (event) => { - if (event.type === RumEventType.ACTION && (event as RumActionEvent).action.target?.name === 'discard me') { - return false - } - }, + notifyRawRumEvent(lifeCycle, { + rawRumEvent: createRawRumEvent(eventType, { date: 100 as TimeStamp }), }) - .build() - notifyRumActionEvent(lifeCycle, 'discard me') - notifyRumActionEvent(lifeCycle, 'discard me') - notifyRumActionEvent(lifeCycle, 'discard me') - notifyRumActionEvent(lifeCycle, 'foo') - expect(serverRumEvents.length).toBe(1) - expect((serverRumEvents[0] as RumActionEvent).action.target?.name).toBe('foo') - expect(reportErrorSpy).not.toHaveBeenCalled() - }) - - it('allows to send new actions after a minute', () => { - const { lifeCycle, clock } = setupBuilder - .withFakeClock() - .withConfiguration({ eventRateLimiterThreshold: 1 }) - .build() - notifyRumActionEvent(lifeCycle, 'foo') - notifyRumActionEvent(lifeCycle, 'bar') - clock.tick(ONE_MINUTE) - notifyRumActionEvent(lifeCycle, 'baz') + notifyRawRumEvent(lifeCycle, { + rawRumEvent: createRawRumEvent(eventType, { date: 100 as TimeStamp }), + }) + notifyRawRumEvent(lifeCycle, { + rawRumEvent: createRawRumEvent(eventType, { date: 200 as TimeStamp }), + }) + expect(serverRumEvents.length).toBe(1) + expect(serverRumEvents[0].date).toBe(200) + expect(reportErrorSpy).not.toHaveBeenCalled() + }) - expect(serverRumEvents.length).toBe(2) - expect((serverRumEvents[0] as RumActionEvent).action.target?.name).toBe('foo') - expect((serverRumEvents[1] as RumActionEvent).action.target?.name).toBe('baz') - }) + it(`allows to send new ${eventType} events after a minute`, () => { + const { lifeCycle, clock } = setupBuilder + .withFakeClock() + .withConfiguration({ eventRateLimiterThreshold: 1 }) + .build() + notifyRawRumEvent(lifeCycle, { + rawRumEvent: createRawRumEvent(eventType, { date: 100 as TimeStamp }), + }) + notifyRawRumEvent(lifeCycle, { + rawRumEvent: createRawRumEvent(eventType, { date: 200 as TimeStamp }), + }) + clock.tick(ONE_MINUTE) + notifyRawRumEvent(lifeCycle, { + rawRumEvent: createRawRumEvent(eventType, { date: 300 as TimeStamp }), + }) - function notifyRumActionEvent(lifeCycle: LifeCycle, name: string) { - const rawRumEvent = createRawRumEvent(RumEventType.ACTION) as RawRumActionEvent - rawRumEvent.action.target.name = name - notifyRawRumEvent(lifeCycle, { - rawRumEvent, + expect(serverRumEvents.length).toBe(2) + expect(serverRumEvents[0].date).toBe(100) + expect(serverRumEvents[1].date).toBe(300) }) - } + }) }) }) diff --git a/packages/rum-core/src/domain/assembly.ts b/packages/rum-core/src/domain/assembly.ts index 3717bb4dd1..ca19dd6a69 100644 --- a/packages/rum-core/src/domain/assembly.ts +++ b/packages/rum-core/src/domain/assembly.ts @@ -114,6 +114,11 @@ export function startRumAssembly( configuration.eventRateLimiterThreshold, reportError ), + [RumEventType.VITAL]: createEventRateLimiter( + RumEventType.VITAL, + configuration.eventRateLimiterThreshold, + reportError + ), } const syntheticsContext = getSyntheticsContext() diff --git a/packages/rum-core/src/domain/vital/vitalCollection.spec.ts b/packages/rum-core/src/domain/vital/vitalCollection.spec.ts index 223a2d664b..a09385f9c9 100644 --- a/packages/rum-core/src/domain/vital/vitalCollection.spec.ts +++ b/packages/rum-core/src/domain/vital/vitalCollection.spec.ts @@ -45,6 +45,16 @@ describe('vitalCollection', () => { expect(rawRumEvents.length).toBe(0) }) + it('should not create multiple duration vitals by calling the stop API multiple times', () => { + const { rawRumEvents } = setupBuilder.build() + + vitalCollection.startDurationVital({ name: 'foo', startClocks: clocksNow() }) + vitalCollection.stopDurationVital({ name: 'foo', stopClocks: clocksNow() }) + vitalCollection.stopDurationVital({ name: 'foo', stopClocks: clocksNow() }) + + expect(rawRumEvents.length).toBe(1) + }) + it('should create multiple duration vitals from start/stop API', () => { const { rawRumEvents, clock } = setupBuilder.build() @@ -73,6 +83,43 @@ describe('vitalCollection', () => { expect(rawRumEvents.length).toBe(1) expect((rawRumEvents[0].rawRumEvent as RawRumVitalEvent).vital.custom.foo).toBe(100) }) + + it('should merge start and stop contexts', () => { + const { rawRumEvents } = setupBuilder.build() + + vitalCollection.startDurationVital({ name: 'both-undefined', startClocks: clocksNow() }) + vitalCollection.stopDurationVital({ name: 'both-undefined', stopClocks: clocksNow() }) + vitalCollection.startDurationVital({ + name: 'start-defined', + startClocks: clocksNow(), + context: { start: 'defined' }, + }) + vitalCollection.stopDurationVital({ name: 'start-defined', stopClocks: clocksNow() }) + vitalCollection.startDurationVital({ name: 'stop-defined', startClocks: clocksNow() }) + vitalCollection.stopDurationVital({ name: 'stop-defined', stopClocks: clocksNow(), context: { stop: 'defined' } }) + vitalCollection.startDurationVital({ + name: 'both-defined', + startClocks: clocksNow(), + context: { start: 'defined' }, + }) + vitalCollection.stopDurationVital({ name: 'both-defined', stopClocks: clocksNow(), context: { stop: 'defined' } }) + vitalCollection.startDurationVital({ + name: 'stop-precedence', + startClocks: clocksNow(), + context: { precedence: 'start' }, + }) + vitalCollection.stopDurationVital({ + name: 'stop-precedence', + stopClocks: clocksNow(), + context: { precedence: 'stop' }, + }) + + expect(rawRumEvents[0].customerContext).toEqual(undefined) + expect(rawRumEvents[1].customerContext).toEqual({ start: 'defined' }) + expect(rawRumEvents[2].customerContext).toEqual({ stop: 'defined' }) + expect(rawRumEvents[3].customerContext).toEqual({ start: 'defined', stop: 'defined' }) + expect(rawRumEvents[4].customerContext).toEqual({ precedence: 'stop' }) + }) }) it('should collect raw rum event from duration vital', () => { diff --git a/packages/rum-core/src/domain/vital/vitalCollection.ts b/packages/rum-core/src/domain/vital/vitalCollection.ts index 278033d51f..f2393f2eca 100644 --- a/packages/rum-core/src/domain/vital/vitalCollection.ts +++ b/packages/rum-core/src/domain/vital/vitalCollection.ts @@ -1,5 +1,5 @@ -import type { ClocksState, Duration } from '@datadog/browser-core' -import { elapsed, generateUUID } from '@datadog/browser-core' +import type { ClocksState, Duration, Context } from '@datadog/browser-core' +import { combine, elapsed, generateUUID } from '@datadog/browser-core' import { LifeCycleEventType } from '../lifeCycle' import type { LifeCycle, RawRumEventCollectedData } from '../lifeCycle' import type { RawRumVitalEvent } from '../../rawRumEvent.types' @@ -8,11 +8,13 @@ import { RumEventType, VitalType } from '../../rawRumEvent.types' export interface DurationVitalStart { name: string startClocks: ClocksState + context?: Context } export interface DurationVitalStop { name: string stopClocks: ClocksState + context?: Context } interface DurationVital { @@ -20,6 +22,7 @@ interface DurationVital { type: VitalType.DURATION startClocks: ClocksState value: Duration + context?: Context } export function startVitalCollection(lifeCycle: LifeCycle) { @@ -38,8 +41,10 @@ export function startVitalCollection(lifeCycle: LifeCycle) { type: VitalType.DURATION, startClocks: vitalStart.startClocks, value: elapsed(vitalStart.startClocks.timeStamp, vitalStop.stopClocks.timeStamp), + context: combine(vitalStart.context, vitalStop.context), } lifeCycle.notify(LifeCycleEventType.RAW_RUM_EVENT_COLLECTED, processVital(vital)) + vitalStartsByName.delete(vitalStop.name) }, } } @@ -58,6 +63,7 @@ function processVital(vital: DurationVital): RawRumEventCollectedData