🔊 [RUMF-1036] Add negative loading time internal monitoring

packages/rum-core/src/domain/rumEventsCollection/action/trackActions.ts

@@ -7,10 +7,10 @@ import {
   generateUUID,
   ClocksState,
   clocksNow,
-  TimeStamp,
   Configuration,
   ONE_SECOND,
   Observable,
+  addMonitoringMessage,
 } from '@datadog/browser-core'
 import { ActionType } from '../../../rawRumEvent.types'
 import { LifeCycle, LifeCycleEventType } from '../../lifeCycle'
@@ -106,7 +106,7 @@ function startActionManagement(lifeCycle: LifeCycle, domMutationObservable: Obse
         domMutationObservable,
         (params) => {
           if (params.hadActivity) {
-            pendingAutoAction.complete(params.endTime)
+            pendingAutoAction.complete(params.endClocks)
           } else {
             pendingAutoAction.discard()
           }
@@ -137,15 +137,28 @@ class PendingAutoAction {
     this.lifeCycle.notify(LifeCycleEventType.AUTO_ACTION_CREATED, { id: this.id, startClocks: this.startClocks })
   }
 
-  complete(endTime: TimeStamp) {
+  complete(endClocks: ClocksState) {
+    const actionDuration = elapsed(this.startClocks.timeStamp, endClocks.timeStamp)
+    if (actionDuration < 0) {
+      addMonitoringMessage('auto action with negative loading time', {
+        debug: {
+          actionDuration,
+          type: this.type,
+          name: this.name,
+          startClocks: this.startClocks,
+          endClocks,
+        },
+      })
+    }
+
     const eventCounts = this.eventCountsSubscription.eventCounts
     this.lifeCycle.notify(LifeCycleEventType.AUTO_ACTION_COMPLETED, {
       counts: {
         errorCount: eventCounts.errorCount,
         longTaskCount: eventCounts.longTaskCount,
         resourceCount: eventCounts.resourceCount,
       },
-      duration: elapsed(this.startClocks.timeStamp, endTime),
+      duration: actionDuration,
       id: this.id,
       name: this.name,
       startClocks: this.startClocks,

packages/rum-core/src/domain/rumEventsCollection/view/trackViewMetrics.ts

@@ -110,7 +110,7 @@ function trackActivityLoadingTime(
   const startTime = timeStampNow()
   const { stop: stopWaitIdlePageActivity } = waitIdlePageActivity(lifeCycle, domMutationObservable, (params) => {
     if (params.hadActivity) {
-      callback(elapsed(startTime, params.endTime))
+      callback(elapsed(startTime, params.endClocks.timeStamp))
     } else {
       callback(undefined)
     }

packages/rum-core/src/domain/trackPageActivities.spec.ts

@@ -177,16 +177,18 @@ describe('waitPageActivitiesCompletion', () => {
 
     expect(completionCallbackSpy).toHaveBeenCalledOnceWith({
       hadActivity: true,
-      // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
-      endTime: (startTime + BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY) as TimeStamp,
+      endClocks: {
+        // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
+        timeStamp: (startTime + BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY) as TimeStamp,
+        relative: BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY,
+      },
     })
   })
 
   describe('extend with activities', () => {
     it('is extended while there is page activities', () => {
       const activityObservable = new Observable<PageActivityEvent>()
       const startTime = timeStampNow()
-
       // Extend the action 10 times
       const extendCount = 10
 
@@ -199,10 +201,14 @@ describe('waitPageActivitiesCompletion', () => {
 
       clock.tick(EXPIRE_DELAY)
 
+      const relative = extendCount * BEFORE_PAGE_ACTIVITY_END_DELAY
       expect(completionCallbackSpy).toHaveBeenCalledOnceWith({
         hadActivity: true,
-        // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
-        endTime: (startTime + extendCount * BEFORE_PAGE_ACTIVITY_END_DELAY) as TimeStamp,
+        endClocks: {
+          // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
+          timeStamp: (startTime + relative) as TimeStamp,
+          relative,
+        },
       })
     })
 
@@ -228,8 +234,11 @@ describe('waitPageActivitiesCompletion', () => {
 
       expect(completionCallbackSpy).toHaveBeenCalledOnceWith({
         hadActivity: true,
-        // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
-        endTime: (startTime + MAX_DURATION) as TimeStamp,
+        endClocks: {
+          // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
+          timeStamp: (startTime + MAX_DURATION) as TimeStamp,
+          relative: MAX_DURATION,
+        },
       })
     })
   })
@@ -248,10 +257,14 @@ describe('waitPageActivitiesCompletion', () => {
 
       clock.tick(EXPIRE_DELAY)
 
+      const relative = BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY + PAGE_ACTIVITY_END_DELAY * 2
       expect(completionCallbackSpy).toHaveBeenCalledOnceWith({
         hadActivity: true,
-        // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
-        endTime: (startTime + BEFORE_PAGE_ACTIVITY_VALIDATION_DELAY + PAGE_ACTIVITY_END_DELAY * 2) as TimeStamp,
+        endClocks: {
+          // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
+          timeStamp: (startTime + relative) as TimeStamp,
+          relative,
+        },
       })
     })
 
@@ -267,8 +280,11 @@ describe('waitPageActivitiesCompletion', () => {
 
       expect(completionCallbackSpy).toHaveBeenCalledOnceWith({
         hadActivity: true,
-        // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
-        endTime: (startTime + MAX_DURATION) as TimeStamp,
+        endClocks: {
+          // eslint-disable-next-line @typescript-eslint/restrict-plus-operands
+          timeStamp: (startTime + MAX_DURATION) as TimeStamp,
+          relative: MAX_DURATION,
+        },
       })
     })
   })

packages/rum-core/src/domain/trackPageActivities.ts

@@ -1,4 +1,4 @@
-import { monitor, Observable, Subscription, TimeStamp, timeStampNow } from '@datadog/browser-core'
+import { clocksNow, ClocksState, monitor, Observable, Subscription } from '@datadog/browser-core'
 import { LifeCycle, LifeCycleEventType } from './lifeCycle'
 
 // Delay to wait for a page activity to validate the tracking process
@@ -10,7 +10,7 @@ export interface PageActivityEvent {
   isBusy: boolean
 }
 
-export type CompletionCallbackParameters = { hadActivity: true; endTime: TimeStamp } | { hadActivity: false }
+export type CompletionCallbackParameters = { hadActivity: true; endClocks: ClocksState } | { hadActivity: false }
 
 export function waitIdlePageActivity(
   lifeCycle: LifeCycle,
@@ -133,17 +133,17 @@ export function waitPageActivitiesCompletion(
   const maxDurationTimeoutId =
     maxDuration &&
     setTimeout(
-      monitor(() => complete({ hadActivity: true, endTime: timeStampNow() })),
+      monitor(() => complete({ hadActivity: true, endClocks: clocksNow() })),
       maxDuration
     )
 
   pageActivitiesObservable.subscribe(({ isBusy }) => {
     clearTimeout(validationTimeoutId)
     clearTimeout(idleTimeoutId)
-    const lastChangeTime = timeStampNow()
+    const lastChangeTime = clocksNow()
     if (!isBusy) {
       idleTimeoutId = setTimeout(
-        monitor(() => complete({ hadActivity: true, endTime: lastChangeTime })),
+        monitor(() => complete({ hadActivity: true, endClocks: lastChangeTime })),
         PAGE_ACTIVITY_END_DELAY
       )
     }