diff --git a/packages/core/src/tools/valueHistory.ts b/packages/core/src/tools/valueHistory.ts index f170ab9b42..86977d7b40 100644 --- a/packages/core/src/tools/valueHistory.ts +++ b/packages/core/src/tools/valueHistory.ts @@ -26,6 +26,7 @@ export interface ValueHistory { closeActive: (endTime: RelativeTime) => void findAll: (startTime?: RelativeTime, duration?: Duration) => Value[] + findAllEntries: (startTime?: RelativeTime, duration?: Duration) => Array> getEntries: (startTime: RelativeTime) => Array> reset: () => void stop: () => void @@ -130,6 +131,19 @@ export function createValueHistory({ .map((entry) => entry.value) } + /** + * Return all entries with an active period overlapping with the duration, + * or all entries that were active during `startTime` if no duration is provided, + * or all currently active entries if no `startTime` is provided. + */ + function findAllEntries( + startTime: RelativeTime = END_OF_TIMES, + duration = 0 as Duration + ): Array> { + const endTime = addDuration(startTime, duration) + return entries.filter((entry) => entry.startTime <= endTime && startTime <= entry.endTime) + } + /** * Return all the entries whose start time is equal to the given startTime. */ @@ -155,7 +169,7 @@ export function createValueHistory({ } } - return { add, find, closeActive, findAll, getEntries, reset, stop } + return { add, find, closeActive, findAll, findAllEntries, getEntries, reset, stop } } /** diff --git a/packages/rum-core/src/domain/lifeCycle.ts b/packages/rum-core/src/domain/lifeCycle.ts index 559d530b9d..f5545544e3 100644 --- a/packages/rum-core/src/domain/lifeCycle.ts +++ b/packages/rum-core/src/domain/lifeCycle.ts @@ -46,7 +46,7 @@ export const enum LifeCycleEventType { RUM_EVENT_COLLECTED, RAW_ERROR_COLLECTED, ACTION_STARTED, - VITAL_STARTED, + DURATION_VITAL_STARTED, } // This is a workaround for an issue occurring when the Browser SDK is included in a TypeScript @@ -79,7 +79,7 @@ declare const LifeCycleEventTypeAsConst: { RAW_RUM_EVENT_COLLECTED: LifeCycleEventType.RAW_RUM_EVENT_COLLECTED RUM_EVENT_COLLECTED: LifeCycleEventType.RUM_EVENT_COLLECTED RAW_ERROR_COLLECTED: LifeCycleEventType.RAW_ERROR_COLLECTED - VITAL_STARTED: LifeCycleEventType.VITAL_STARTED + DURATION_VITAL_STARTED: LifeCycleEventType.DURATION_VITAL_STARTED } // Note: this interface needs to be exported even if it is not used outside of this module, else TS @@ -104,7 +104,7 @@ export interface LifeCycleEventMap { error: RawError customerContext?: Context } - [LifeCycleEventTypeAsConst.VITAL_STARTED]: DurationVitalStart + [LifeCycleEventTypeAsConst.DURATION_VITAL_STARTED]: DurationVitalStart } export interface RawRumEventCollectedData { diff --git a/packages/rum-core/src/domain/vital/vitalCollection.spec.ts b/packages/rum-core/src/domain/vital/vitalCollection.spec.ts index 481710c105..d7f68c4cf9 100644 --- a/packages/rum-core/src/domain/vital/vitalCollection.spec.ts +++ b/packages/rum-core/src/domain/vital/vitalCollection.spec.ts @@ -211,7 +211,7 @@ describe('vitalCollection', () => { it('should notify lifecycle with vital started event when starting a duration vital', () => { const subscriberSpy = jasmine.createSpy() - lifeCycle.subscribe(LifeCycleEventType.VITAL_STARTED, subscriberSpy) + lifeCycle.subscribe(LifeCycleEventType.DURATION_VITAL_STARTED, subscriberSpy) vitalCollection.startDurationVital('foo') diff --git a/packages/rum-core/src/domain/vital/vitalCollection.ts b/packages/rum-core/src/domain/vital/vitalCollection.ts index 43901949c4..6113e2f5c8 100644 --- a/packages/rum-core/src/domain/vital/vitalCollection.ts +++ b/packages/rum-core/src/domain/vital/vitalCollection.ts @@ -142,7 +142,7 @@ export function startVitalCollection(lifeCycle: LifeCycle, pageStateHistory: Pag name, ...options, }) - lifeCycle.notify(LifeCycleEventType.VITAL_STARTED, { id, name, startClocks, ...options }) + lifeCycle.notify(LifeCycleEventType.DURATION_VITAL_STARTED, { id, name, startClocks, ...options }) } function stopDurationVital(name: string, options: DurationVitalOptions = {}, stopClocks = clocksNow()) { diff --git a/packages/rum-core/src/index.ts b/packages/rum-core/src/index.ts index 920860d839..29fbe4097d 100644 --- a/packages/rum-core/src/index.ts +++ b/packages/rum-core/src/index.ts @@ -23,7 +23,7 @@ export type { RumVitalEventDomainContext, } from './domainContext.types' export type { ReplayStats, RawRumActionEvent, RawRumEvent } from './rawRumEvent.types' -export { ActionType, RumEventType, FrustrationType, RumLongTaskEntryType } from './rawRumEvent.types' +export { ActionType, RumEventType, FrustrationType, RumLongTaskEntryType, VitalType } from './rawRumEvent.types' export { startRum } from './boot/startRum' export type { RawRumEventCollectedData } from './domain/lifeCycle' export { LifeCycle, LifeCycleEventType } from './domain/lifeCycle' diff --git a/packages/rum/src/domain/profiling/datadogProfiler.ts b/packages/rum/src/domain/profiling/datadogProfiler.ts index 7b07c018eb..6a2ec7ba53 100644 --- a/packages/rum/src/domain/profiling/datadogProfiler.ts +++ b/packages/rum/src/domain/profiling/datadogProfiler.ts @@ -229,7 +229,12 @@ export function createRumProfiler( const duration = elapsed(startClocks.relative, endClocks.relative) const longTasks = longTaskHistory.findAll(startClocks.relative, duration) const actions = actionHistory.findAll(startClocks.relative, duration) - const vitals = vitalHistory.findAll(startClocks.relative, duration) + const vitals = vitalHistory.findAll(startClocks.relative, duration).map((vital) => ({ + id: vital.id, + label: vital.label, + startClocks: vital.startClocks, + duration: vital.duration, + })) const isBelowDurationThreshold = duration < profilerConfiguration.minProfileDurationMs if (longTasks.length === 0 && isBelowDurationThreshold) { diff --git a/packages/rum/src/domain/profiling/profiler.spec.ts b/packages/rum/src/domain/profiling/profiler.spec.ts index deb614320f..22770e9206 100644 --- a/packages/rum/src/domain/profiling/profiler.spec.ts +++ b/packages/rum/src/domain/profiling/profiler.spec.ts @@ -1,5 +1,11 @@ import type { ViewHistoryEntry } from '@datadog/browser-rum-core' -import { LifeCycle, LifeCycleEventType, RumPerformanceEntryType, createHooks } from '@datadog/browser-rum-core' +import { + LifeCycle, + LifeCycleEventType, + RumPerformanceEntryType, + VitalType, + createHooks, +} from '@datadog/browser-rum-core' import type { Duration, SessionRenewalEvent } from '@datadog/browser-core' import { addDuration, @@ -8,6 +14,7 @@ import { createIdentityEncoder, createValueHistory, deepClone, + elapsed, ONE_DAY, relativeNow, timeStampNow, @@ -141,6 +148,18 @@ describe('profiler', () => { addVital: (vital: VitalContext) => { vitalHistory.add(vital, relativeNow()).close(addDuration(relativeNow(), vital.duration ?? (0 as Duration))) }, + startOperationStep: (id: string, label: string, operationKey?: string) => { + const startClocks = clocksNow() + const entry = vitalHistory.add( + { id, type: VitalType.OPERATION_STEP, label, operationKey, startClocks, duration: undefined }, + startClocks.relative + ) + return () => { + const endTime = relativeNow() + entry.value.duration = elapsed(entry.startTime, endTime) + entry.close(endTime) + } + }, } } @@ -415,6 +434,7 @@ describe('profiler', () => { expect(profilingContextManager.get()?.status).toBe('running') addVital({ id: 'vital-id-1', + type: VitalType.DURATION, label: 'vital-label-1', startClocks: clocksNow(), duration: 50 as Duration, @@ -423,6 +443,7 @@ describe('profiler', () => { addVital({ id: 'vital-id-2', + type: VitalType.DURATION, label: 'vital-label-2', startClocks: clocksNow(), duration: 100 as Duration, @@ -442,6 +463,7 @@ describe('profiler', () => { addVital({ id: 'vital-id-3', + type: VitalType.DURATION, label: 'vital-label-3', startClocks: clocksNow(), duration: 100 as Duration, @@ -495,6 +517,79 @@ describe('profiler', () => { ]) }) + it('should collect all ongoing operations during a profiling session', async () => { + const clock = mockClock() + const { profiler, startOperationStep } = setupProfiler() + + // Profile 1: start all three operations, end op1 + profiler.start() + await waitForBoolean(() => profiler.isRunning()) + + const endOp1 = startOperationStep('op-id-1', 'op-label-1') + clock.tick(10) + const endOp2 = startOperationStep('op-id-2', 'op-label-2') + clock.tick(10) + const endOp3 = startOperationStep('op-id-3', 'op-label-3') + clock.tick(10) + endOp1() // op1 ends during profile 1 + + clock.tick(70) + profiler.stop() + await waitNextMicrotask() + + // Profile 2: end op2 + profiler.start() + await waitForBoolean(() => profiler.isRunning()) + + clock.tick(50) + endOp2() // op2 ends during profile 2 + + clock.tick(50) + profiler.stop() + await waitNextMicrotask() + + // Profile 3: end op3 + profiler.start() + await waitForBoolean(() => profiler.isRunning()) + + clock.tick(50) + endOp3() // op3 ends during profile 3 + + clock.tick(50) + profiler.stop() + await waitNextMicrotask() + await waitNextMicrotask() + + expect(interceptor.requests.length).toBe(3) + + const req1 = await readFormDataRequest(interceptor.requests[0]) + const req2 = await readFormDataRequest(interceptor.requests[1]) + const req3 = await readFormDataRequest(interceptor.requests[2]) + + const vitals1 = req1['wall-time.json'].vitals + const vitals2 = req2['wall-time.json'].vitals + const vitals3 = req3['wall-time.json'].vitals + + // Profile 1: all three operations present, only op1 has a duration + expect(vitals1?.map((v) => v.id)).toEqual(jasmine.arrayContaining(['op-id-1', 'op-id-2', 'op-id-3'])) + expect(vitals1?.find((v) => v.id === 'op-id-1')?.duration).toBe(30 as Duration) + expect(vitals1?.find((v) => v.id === 'op-id-2')?.duration).toBeUndefined() + expect(vitals1?.find((v) => v.id === 'op-id-3')?.duration).toBeUndefined() + + // Profile 2: op1 is gone (ended before profile 2 started), op2 and op3 present, only op2 has a duration + expect(vitals2?.map((v) => v.id)).not.toContain('op-id-1') + expect(vitals2?.map((v) => v.id)).toEqual(jasmine.arrayContaining(['op-id-2', 'op-id-3'])) + expect(vitals2?.find((v) => v.id === 'op-id-2')?.duration).toBe(140 as Duration) + expect(vitals2?.find((v) => v.id === 'op-id-3')?.duration).toBeUndefined() + + // Profile 3: only op3 remains, with a duration + expect(vitals3?.map((v) => v.id)).not.toContain('op-id-1') + expect(vitals3?.map((v) => v.id)).not.toContain('op-id-2') + expect(vitals3?.length).toBe(1) + expect(vitals3?.[0].id).toBe('op-id-3') + expect(vitals3?.[0].duration).toBe(230 as Duration) + }) + it('should collect views and set default view name in the Profile', async () => { const initialViewEntry = { id: 'view-user', diff --git a/packages/rum/src/domain/profiling/vitalHistory.spec.ts b/packages/rum/src/domain/profiling/vitalHistory.spec.ts index 600a9eba1c..f1d52fd16e 100644 --- a/packages/rum/src/domain/profiling/vitalHistory.spec.ts +++ b/packages/rum/src/domain/profiling/vitalHistory.spec.ts @@ -1,5 +1,5 @@ import { relativeToClocks, type Duration, type RelativeTime } from '@datadog/browser-core' -import { LifeCycle, LifeCycleEventType, RumEventType } from '@datadog/browser-rum-core' +import { LifeCycle, LifeCycleEventType, RumEventType, VitalType } from '@datadog/browser-rum-core' import { createRawRumEvent } from '@datadog/browser-rum-core/test' import { createVitalHistory } from './vitalHistory' @@ -40,9 +40,11 @@ describe('vitalHistory', () => { expect(history.findAll(5 as RelativeTime, 30 as RelativeTime)).toEqual([ { id: 'vital-123', + type: VitalType.DURATION, startClocks, duration: 20 as Duration, label: 'vital-name', + operationKey: undefined, }, ]) }) @@ -136,10 +138,10 @@ describe('vitalHistory', () => { ]) }) - it('should add a vital to the history with duration 0 when VITAL_STARTED is triggered', () => { + it('should add a vital to the history with duration 0 when DURATION_VITAL_STARTED is triggered', () => { const history = createVitalHistory(lifeCycle) - lifeCycle.notify(LifeCycleEventType.VITAL_STARTED, { + lifeCycle.notify(LifeCycleEventType.DURATION_VITAL_STARTED, { id: 'vital-1', name: 'vital-name-1', startClocks: relativeToClocks(10 as RelativeTime), @@ -151,10 +153,10 @@ describe('vitalHistory', () => { expect(matchingVitals[0].duration).toBeUndefined() }) - it('should add a vital to the history when VITAL_STARTED is triggered, and close it when RAW_RUM_EVENT_COLLECTED is triggered', () => { + it('should add a vital to the history when DURATION_VITAL_STARTED is triggered, and close it when RAW_RUM_EVENT_COLLECTED is triggered', () => { const history = createVitalHistory(lifeCycle) - lifeCycle.notify(LifeCycleEventType.VITAL_STARTED, { + lifeCycle.notify(LifeCycleEventType.DURATION_VITAL_STARTED, { id: 'vital-1', name: 'vital-name-1', startClocks: relativeToClocks(10 as RelativeTime), @@ -184,13 +186,13 @@ describe('vitalHistory', () => { it('should be able to handle multiple vitals being started and stopped', () => { const history = createVitalHistory(lifeCycle) - lifeCycle.notify(LifeCycleEventType.VITAL_STARTED, { + lifeCycle.notify(LifeCycleEventType.DURATION_VITAL_STARTED, { id: 'vital-1', name: 'vital-name-1', startClocks: relativeToClocks(10 as RelativeTime), }) - lifeCycle.notify(LifeCycleEventType.VITAL_STARTED, { + lifeCycle.notify(LifeCycleEventType.DURATION_VITAL_STARTED, { id: 'vital-2', name: 'vital-name-2', startClocks: relativeToClocks(10 as RelativeTime), @@ -234,5 +236,105 @@ describe('vitalHistory', () => { expect(matchingVitals.map((vital) => vital.duration)).toEqual([20 as Duration, 20 as Duration]) }) + + function notifyOperationStep( + name: string, + stepType: 'start' | 'end', + relativeTime: RelativeTime, + operationKey?: string + ) { + lifeCycle.notify(LifeCycleEventType.RAW_RUM_EVENT_COLLECTED, { + rawRumEvent: createRawRumEvent(RumEventType.VITAL, { + vital: { + id: `${name}-${stepType}`, + type: VitalType.OPERATION_STEP, + name, + step_type: stepType, + operation_key: operationKey, + }, + }), + startClocks: relativeToClocks(relativeTime), + duration: undefined, + domainContext: fakeDomainContext, + }) + } + + it('should add a start operation step to the history with undefined duration', () => { + const history = createVitalHistory(lifeCycle) + + notifyOperationStep('op-name', 'start', 10 as RelativeTime) + + const vitals = history.findAll(10 as RelativeTime, 10 as Duration) + expect(vitals.length).toBe(1) + expect(vitals[0].label).toBe('op-name') + expect(vitals[0].duration).toBeUndefined() + }) + + it('should not add an end-only operation step to the history', () => { + const history = createVitalHistory(lifeCycle) + + notifyOperationStep('op-name', 'end', 30 as RelativeTime) + + expect(history.findAll(0 as RelativeTime, 100 as Duration)).toEqual([]) + }) + + it('should update the start vital with the correct duration and entry end time when the matching end step arrives', () => { + const history = createVitalHistory(lifeCycle) + + notifyOperationStep('op-name', 'start', 10 as RelativeTime) + notifyOperationStep('op-name', 'end', 50 as RelativeTime) + + // This checks that the entry duration was updated too + const vitals = history.findAll(35 as RelativeTime, 20 as Duration) + expect(vitals.length).toBe(1) + expect(vitals[0].label).toBe('op-name') + expect(vitals[0].duration).toBe(40 as Duration) + }) + + it('should only update the vital whose name matches the end step', () => { + const history = createVitalHistory(lifeCycle) + + notifyOperationStep('op-a', 'start', 10 as RelativeTime) + notifyOperationStep('op-b', 'start', 20 as RelativeTime) + notifyOperationStep('op-a', 'end', 50 as RelativeTime) + + const vitals = history.findAll(0 as RelativeTime, 100 as Duration) + const opA = vitals.find((v) => v.label === 'op-a') + const opB = vitals.find((v) => v.label === 'op-b') + + expect(opA?.duration).toBe(40 as Duration) + expect(opB?.duration).toBeUndefined() + }) + + it('should match start/end by both name and operationKey', () => { + const history = createVitalHistory(lifeCycle) + + notifyOperationStep('op-name', 'start', 10 as RelativeTime, 'key1') + notifyOperationStep('op-name', 'start', 20 as RelativeTime, 'key2') + notifyOperationStep('op-name', 'end', 50 as RelativeTime, 'key1') + + const vitals = history.findAll(0 as RelativeTime, 100 as Duration) + const key1 = vitals.find((v) => v.operationKey === 'key1') + const key2 = vitals.find((v) => v.operationKey === 'key2') + + expect(key1?.duration).toBe(40 as Duration) + expect(key2?.duration).toBeUndefined() + }) + + it('should update both vitals independently when their respective end steps arrive', () => { + const history = createVitalHistory(lifeCycle) + + notifyOperationStep('op-name', 'start', 10 as RelativeTime, 'key1') + notifyOperationStep('op-name', 'start', 20 as RelativeTime, 'key2') + notifyOperationStep('op-name', 'end', 50 as RelativeTime, 'key1') + notifyOperationStep('op-name', 'end', 80 as RelativeTime, 'key2') + + const vitals = history.findAll(0 as RelativeTime, 100 as Duration) + const key1 = vitals.find((v) => v.operationKey === 'key1') + const key2 = vitals.find((v) => v.operationKey === 'key2') + + expect(key1?.duration).toBe(40 as Duration) + expect(key2?.duration).toBe(60 as Duration) + }) }) }) diff --git a/packages/rum/src/domain/profiling/vitalHistory.ts b/packages/rum/src/domain/profiling/vitalHistory.ts index cc904e46dc..67eee5fe55 100644 --- a/packages/rum/src/domain/profiling/vitalHistory.ts +++ b/packages/rum/src/domain/profiling/vitalHistory.ts @@ -1,13 +1,15 @@ import type { ClocksState, Duration } from '@datadog/browser-core' -import { addDuration, createValueHistory, SESSION_TIME_OUT_DELAY } from '@datadog/browser-core' +import { addDuration, createValueHistory, elapsed, SESSION_TIME_OUT_DELAY } from '@datadog/browser-core' import type { LifeCycle } from '@datadog/browser-rum-core' -import { LifeCycleEventType } from '@datadog/browser-rum-core' +import { LifeCycleEventType, VitalType } from '@datadog/browser-rum-core' export const VITAL_ID_HISTORY_TIME_OUT_DELAY = SESSION_TIME_OUT_DELAY export interface VitalContext { id: string + type: VitalType label: string + operationKey?: string duration?: Duration startClocks: ClocksState } @@ -17,10 +19,11 @@ export function createVitalHistory(lifeCycle: LifeCycle) { expireDelay: VITAL_ID_HISTORY_TIME_OUT_DELAY, }) - lifeCycle.subscribe(LifeCycleEventType.VITAL_STARTED, (vitalStart) => { + lifeCycle.subscribe(LifeCycleEventType.DURATION_VITAL_STARTED, (vitalStart) => { history.add( { id: vitalStart.id, + type: VitalType.DURATION, startClocks: vitalStart.startClocks, duration: undefined, label: vitalStart.name, @@ -30,28 +33,72 @@ export function createVitalHistory(lifeCycle: LifeCycle) { }) lifeCycle.subscribe(LifeCycleEventType.RAW_RUM_EVENT_COLLECTED, ({ rawRumEvent, startClocks, duration }) => { - if (rawRumEvent.type === 'vital') { - const historyEntry = history - .getEntries(startClocks.relative) - .find((entry) => entry.value.id === rawRumEvent.vital.id) - - if (historyEntry) { - historyEntry.value.duration = duration! - historyEntry.close(addDuration(startClocks.relative, duration!)) - } else { - history - .add( - { - id: rawRumEvent.vital.id, - startClocks, - duration, - label: rawRumEvent.vital.name, - }, - startClocks.relative + if (rawRumEvent.type !== 'vital') { + return + } + + // For operation step vitals, we only tag profiles with the start step's id. + // This means that if we receive an end step vital, we need to look for the + // corresponding start one and update its duration. If we receive a start step vital + // however, we just store it and wait for the end step. + if (rawRumEvent.vital.type === VitalType.OPERATION_STEP) { + if (rawRumEvent.vital.step_type === 'start') { + history.add( + { + id: rawRumEvent.vital.id, + type: rawRumEvent.vital.type, + operationKey: rawRumEvent.vital.operation_key, + startClocks, + label: rawRumEvent.vital.name, + }, + startClocks.relative + ) + } else if (rawRumEvent.vital.step_type === 'end') { + const historyEntry = history + .findAllEntries() + .find( + (entry) => + entry.value.type === VitalType.OPERATION_STEP && + entry.value.label === rawRumEvent.vital.name && + entry.value.operationKey === rawRumEvent.vital.operation_key ) - .close(addDuration(startClocks.relative, duration!)) + + if (!historyEntry) { + return + } + + historyEntry.value.duration = elapsed(historyEntry.value.startClocks.relative, startClocks.relative) + historyEntry.close(startClocks.relative) } + + return } + + // All the other vital types are handled normally (i.e. stored in the + // history and tagged on the profiles) + const historyEntry = history + .getEntries(startClocks.relative) + .find((entry) => entry.value.id === rawRumEvent.vital.id) + + if (historyEntry) { + historyEntry.value.duration = duration! + historyEntry.close(addDuration(startClocks.relative, duration!)) + return + } + + history + .add( + { + id: rawRumEvent.vital.id, + type: rawRumEvent.vital.type, + operationKey: rawRumEvent.vital.operation_key, + startClocks, + duration, + label: rawRumEvent.vital.name, + }, + startClocks.relative + ) + .close(addDuration(startClocks.relative, duration!)) }) return history