⚗ [RUMF-971] experiment to detect when the computer goes to sleep (#976)

* ⚗ [RUMF-971] experiment to detect when the computer goes to sleep

* [RUMF-971] add sleep duration on resources `_dd.sleep_duration`

* 🔊 [RUMF-971] add sleep duration to resource > 1 day IML context

* 🔊 [RUMF-971] add sleep duration to view timings > 1 day IML context

* 🔊 display "context" when printing an internal monitoring log

* 👌 rename variable

packages/core/src/domain/internalMonitoring.ts

@@ -140,7 +140,7 @@ export function callMonitored<T extends (...args: any[]) => any>(
 }
 
 export function addMonitoringMessage(message: string, context?: Context) {
-  logMessageIfDebug(message)
+  logMessageIfDebug(message, context)
   addToMonitoringBatch({
     message,
     ...context,
@@ -195,8 +195,8 @@ function logErrorIfDebug(e: any) {
   }
 }
 
-function logMessageIfDebug(message: any) {
+function logMessageIfDebug(message: any, context?: Context) {
   if (monitoringConfiguration.debugMode) {
-    display.log('[MONITORING MESSAGE]', message)
+    display.log('[MONITORING MESSAGE]', message, context)
   }
 }

packages/rum-core/src/boot/startRum.ts

@@ -13,6 +13,7 @@ import { startLongTaskCollection } from '../domain/rumEventsCollection/longTask/
 import { startResourceCollection } from '../domain/rumEventsCollection/resource/resourceCollection'
 import { startViewCollection } from '../domain/rumEventsCollection/view/viewCollection'
 import { RumSession, startRumSession } from '../domain/rumSession'
+import { trackSleep } from '../domain/trackSleep'
 import { CommonContext } from '../rawRumEvent.types'
 import { startRumBatch } from '../transport/batch'
 import { RumInitConfiguration } from './rumPublicApi'
@@ -46,6 +47,10 @@ export function startRum(
     getCommonContext
   )
 
+  if (configuration.isEnabled('track-sleep')) {
+    trackSleep()
+  }
+
   if (session.hasReplayPlan()) {
     startLongTaskCollection(lifeCycle)
   }

packages/rum-core/src/domain/rumEventsCollection/resource/resourceCollection.ts

@@ -5,6 +5,7 @@ import {
   ResourceType,
   toServerDuration,
   relativeToClocks,
+  TimeStamp,
 } from '@datadog/browser-core'
 import {
   RumPerformanceEntry,
@@ -19,6 +20,7 @@ import {
 import { RawRumResourceEvent, RumEventType } from '../../../rawRumEvent.types'
 import { LifeCycle, LifeCycleEventType, RawRumEventCollectedData } from '../../lifeCycle'
 import { RequestCompleteEvent } from '../../requestCollection'
+import { getSleepDuration } from '../../trackSleep'
 import { matchRequestTiming } from './matchRequestTiming'
 import {
   computePerformanceResourceDetails,
@@ -63,7 +65,8 @@ function processRequest(request: RequestCompleteEvent): RawRumEventCollectedData
       type: RumEventType.RESOURCE as const,
     },
     tracingInfo,
-    correspondingTimingOverrides
+    correspondingTimingOverrides,
+    computeSleepInfo(startClocks.timeStamp)
   )
   return {
     startTime: startClocks.relative,
@@ -96,7 +99,8 @@ function processResourceEntry(entry: RumPerformanceResourceTiming): RawRumEventC
       type: RumEventType.RESOURCE as const,
     },
     tracingInfo,
-    entryMetrics
+    entryMetrics,
+    computeSleepInfo(startClocks.timeStamp)
   )
   return {
     startTime: startClocks.relative,
@@ -134,6 +138,17 @@ function computeEntryTracingInfo(entry: RumPerformanceResourceTiming) {
   return entry.traceId ? { _dd: { trace_id: entry.traceId } } : undefined
 }
 
+function computeSleepInfo(date: TimeStamp) {
+  const sleepDuration = getSleepDuration(date)
+  if (sleepDuration > 0) {
+    return {
+      _dd: {
+        sleep_duration: sleepDuration,
+      },
+    }
+  }
+}
+
 function toPerformanceEntryRepresentation(entry: RumPerformanceEntry): PerformanceEntryRepresentation {
   if (supportPerformanceEntry() && entry instanceof PerformanceEntry) {
     entry.toJSON()

packages/rum-core/src/domain/rumEventsCollection/resource/resourceUtils.ts

@@ -12,10 +12,12 @@ import {
   ONE_DAY,
   relativeNow,
   timeStampNow,
+  TimeStamp,
 } from '@datadog/browser-core'
 import { RumPerformanceResourceTiming } from '../../../browser/performanceCollection'
 
 import { PerformanceResourceDetailsElement } from '../../../rawRumEvent.types'
+import { getSleepDuration } from '../../trackSleep'
 
 export interface PerformanceResourceDetails {
   redirect?: PerformanceResourceDetailsElement
@@ -95,6 +97,7 @@ export function computePerformanceResourceDuration(entry: RumPerformanceResource
         duration: Math.round(duration),
         relativeNow: Math.round(relativeNow()),
         timeStampNow: timeStampNow(),
+        sleepDuration: getSleepDuration((timeStampNow() - duration) as TimeStamp),
       },
     })
   }

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

@@ -11,6 +11,7 @@ import {
   timeStampNow,
 } from '@datadog/browser-core'
 import { LifeCycle, LifeCycleEventType } from '../../lifeCycle'
+import { getSleepDuration } from '../../trackSleep'
 import { trackFirstHidden } from './trackFirstHidden'
 
 export interface Timings {
@@ -86,6 +87,7 @@ export function trackFirstContentfulPaint(lifeCycle: LifeCycle, callback: (fcp:
             fcp: Math.round(entry.startTime),
             relativeNow: Math.round(relativeNow()),
             timeStampNow: timeStampNow(),
+            sleepDuration: getSleepDuration(),
           },
         })
       }
@@ -135,6 +137,7 @@ export function trackLargestContentfulPaint(
               lcp: Math.round(entry.startTime),
               relativeNow: Math.round(relativeNow()),
               timeStampNow: timeStampNow(),
+              sleepDuration: getSleepDuration(),
             },
           })
         }

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

@@ -0,0 +1,70 @@
+import { TimeStamp } from '@datadog/browser-core'
+import { SLEEP_THRESHOLD, trackSleep, getSleepDuration, SLEEP_CHECK_DELAY } from './trackSleep'
+
+describe('trackSleep', () => {
+  let stopSleepTracking: () => void
+  let setIntervalCallback: () => void
+  let dateNowSpy: jasmine.Spy<typeof Date.now>
+
+  beforeEach(() => {
+    // Jasmine date mock doesn't work here because it keeps the time and timeouts exactly
+    // synchronized, and we specifically want to detect when they drift away.
+    dateNowSpy = spyOn(Date, 'now').and.returnValue(0)
+    spyOn(window, 'setInterval').and.callFake((callback) => {
+      setIntervalCallback = callback as () => void
+      return 1
+    })
+    ;({ stop: stopSleepTracking } = trackSleep())
+  })
+
+  afterEach(() => {
+    stopSleepTracking()
+  })
+
+  describe('getSleepDuration', () => {
+    it('returns 0 if it was not previously sleeping', () => {
+      tick(SLEEP_THRESHOLD - 1)
+      expect(getSleepDuration()).toBe(0)
+    })
+
+    it('returns the sleep duration if it was previously sleeping', () => {
+      tick(SLEEP_THRESHOLD)
+      expect(getSleepDuration()).toBe(SLEEP_THRESHOLD)
+    })
+
+    it('returns 0 if it was not sleeping since a given timestamp', () => {
+      tick(SLEEP_THRESHOLD)
+      expect(getSleepDuration((SLEEP_THRESHOLD + 1) as TimeStamp)).toBe(0)
+    })
+
+    it('returns the sleep duration if it was sleeping since a given timestamp', () => {
+      tick(SLEEP_THRESHOLD)
+      expect(getSleepDuration(0 as TimeStamp)).toBe(SLEEP_THRESHOLD)
+    })
+
+    it('collects the sleep periods across time', () => {
+      tick(SLEEP_CHECK_DELAY)
+      setIntervalCallback()
+
+      // Sleep now
+      tick(SLEEP_THRESHOLD)
+      setIntervalCallback()
+
+      tick(SLEEP_CHECK_DELAY)
+      setIntervalCallback()
+
+      // Sleep now
+      tick(SLEEP_THRESHOLD)
+      setIntervalCallback()
+
+      setIntervalCallback()
+      tick(SLEEP_CHECK_DELAY)
+
+      expect(getSleepDuration(SLEEP_CHECK_DELAY as TimeStamp)).toBe(SLEEP_THRESHOLD * 2)
+    })
+  })
+
+  function tick(delay: number) {
+    dateNowSpy.and.returnValue(dateNowSpy() + delay)
+  }
+})

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

@@ -0,0 +1,39 @@
+import { monitor, ONE_MINUTE, ONE_SECOND, TimeStamp, timeStampNow } from '@datadog/browser-core'
+
+export const SLEEP_CHECK_DELAY = ONE_SECOND
+export const SLEEP_THRESHOLD = ONE_MINUTE
+
+let sleepPeriods: Array<{ start: TimeStamp; end: TimeStamp }> | undefined
+let lastWoke: TimeStamp | undefined
+
+export function trackSleep() {
+  lastWoke = timeStampNow()
+  sleepPeriods = []
+  const intervalId = setInterval(monitor(checkSleep), SLEEP_CHECK_DELAY)
+  return { stop: () => clearInterval(intervalId) }
+}
+
+export function getSleepDuration(since?: TimeStamp) {
+  if (!sleepPeriods) {
+    return 0
+  }
+  checkSleep()
+  let filteredPeriods
+  if (since === undefined) {
+    filteredPeriods = sleepPeriods
+  } else {
+    filteredPeriods = sleepPeriods.filter((period) => period.end >= since)
+  }
+  return filteredPeriods.reduce((total, period) => total + (period.end - period.start), 0)
+}
+
+function checkSleep() {
+  if (lastWoke === undefined || !sleepPeriods) {
+    return
+  }
+  const now = timeStampNow()
+  if (now - lastWoke >= SLEEP_THRESHOLD) {
+    sleepPeriods.push({ start: lastWoke, end: now })
+  }
+  lastWoke = now
+}

packages/rum-core/src/rawRumEvent.types.ts

@@ -36,8 +36,9 @@ export interface RawRumResourceEvent {
     download?: PerformanceResourceDetailsElement
   }
   _dd?: {
-    trace_id: string
+    trace_id?: string
     span_id?: string // not available for initial document tracing
+    sleep_duration?: number
   }
 }
 

packages/rum/src/domain/segmentCollection/segment.spec.ts

@@ -130,7 +130,8 @@ describe('Segment', () => {
     expect(worker.listenersCount).toBe(1)
     expect(displaySpy).toHaveBeenCalledWith(
       '[MONITORING MESSAGE]',
-      "Segment did not receive a 'flush' response before being replaced."
+      "Segment did not receive a 'flush' response before being replaced.",
+      undefined
     )
   })
 })