Merge pull request #2582 from DataDog/tvaleev/feature/RUM-9361-negative

[RUM-9361] fixing negative values in slow frames, adjusting telemetry

Author: satween

features/dd-sdk-android-rum/src/main/kotlin/com/datadog/android/rum/internal/domain/scope/RumViewScope.kt

@@ -898,7 +898,7 @@ internal open class RumViewScope(
         // make a copy - by the time we iterate over it on another thread, it may already be changed
         val eventFeatureFlags = featureFlags.toMutableMap()
         val eventAdditionalAttributes = (eventAttributes + globalAttributes).toMutableMap()
-        val uiSlownessReport = slowFramesListener?.resolveReport(viewId, viewComplete)
+        val uiSlownessReport = slowFramesListener?.resolveReport(viewId, viewComplete, durationNs)
         val slowFrames = uiSlownessReport?.slowFramesRecords?.map {
             ViewEvent.SlowFrame(
                 start = it.startTimestampNs - startedNanos,

features/dd-sdk-android-rum/src/main/kotlin/com/datadog/android/rum/internal/metric/slowframes/SlowFramesListener.kt

@@ -16,7 +16,7 @@ import kotlin.math.min
 
 internal interface SlowFramesListener : FrameStateListener {
     fun onViewCreated(viewId: String, startedTimestampNs: Long)
-    fun resolveReport(viewId: String, isViewCompleted: Boolean): ViewUIPerformanceReport?
+    fun resolveReport(viewId: String, isViewCompleted: Boolean, viewDurationNs: Long): ViewUIPerformanceReport?
     fun onAddLongTask(durationNs: Long)
 }
 
@@ -41,22 +41,37 @@ internal class DefaultSlowFramesListener(
     }
 
     // Called from the main thread
-    override fun resolveReport(viewId: String, isViewCompleted: Boolean): ViewUIPerformanceReport? {
+    override fun resolveReport(
+        viewId: String,
+        isViewCompleted: Boolean,
+        viewDurationNs: Long
+    ): ViewUIPerformanceReport? {
         @Suppress("UnsafeThirdPartyFunctionCall") // can't have NPE here
         val report = if (isViewCompleted) slowFramesRecords.remove(viewId) else slowFramesRecords[viewId]
 
         if (report == null) return null
 
         // making sure that report is not partially updated
         return synchronized(report) {
-            if (isViewCompleted) metricDispatcher.sendMetric(viewId)
+            if (isViewCompleted) metricDispatcher.sendMetric(viewId, viewDurationNs)
             report.copy()
         }
     }
 
     // Called from the background thread
     override fun onFrame(volatileFrameData: FrameData) {
-        val viewId = currentViewId ?: return
+        val viewId = currentViewId
+        if (viewId == null || volatileFrameData.frameStartNanos < currentViewStartedTimeStampNs) {
+            if (viewId != null) {
+                metricDispatcher.incrementMissedFrameCount(viewId)
+            }
+            // Due to the asynchronous nature of collecting jank frames data, there is a possible situation where
+            // androidx.performance.metrics started detecting jank frames on a previous view, but reported them after the new view
+            // was started. In this case, we don't save this data, because the previous view has already
+            // sent its report, so there is no way to add more data to it, adding a slow frame to the
+            // current view, would be also wrong, so we just drop such frame data.
+            return
+        }
         val frameDurationNs = volatileFrameData.frameDurationUiNanos
         val frameStartedTimestampNs = volatileFrameData.frameStartNanos
         val report = getViewPerformanceReport(viewId)

features/dd-sdk-android-rum/src/main/kotlin/com/datadog/android/rum/internal/metric/slowframes/UISlownessMetricDispatcher.kt

@@ -21,7 +21,9 @@ internal interface UISlownessMetricDispatcher {
 
     fun incrementIgnoredFrameCount(viewId: String)
 
-    fun sendMetric(viewId: String)
+    fun incrementMissedFrameCount(viewId: String)
+
+    fun sendMetric(viewId: String, viewDurationNs: Long)
 }
 
 internal class DefaultUISlownessMetricDispatcher(
@@ -32,7 +34,8 @@ internal class DefaultUISlownessMetricDispatcher(
 
     internal data class SlowFramesTelemetry(
         val slowFramesCount: AtomicInteger = AtomicInteger(0),
-        val ignoredFramesCount: AtomicInteger = AtomicInteger(0)
+        val ignoredFramesCount: AtomicInteger = AtomicInteger(0),
+        val missedFrameCount: AtomicInteger = AtomicInteger(0)
     )
 
     private val viewTelemetry = ConcurrentHashMap<String, SlowFramesTelemetry>()
@@ -52,8 +55,13 @@ internal class DefaultUISlownessMetricDispatcher(
         viewTelemetry[viewId]?.ignoredFramesCount?.incrementAndGet()
     }
 
+    // Called from the background thread
+    override fun incrementMissedFrameCount(viewId: String) {
+        viewTelemetry[viewId]?.missedFrameCount?.incrementAndGet()
+    }
+
     // Called from the main thread
-    override fun sendMetric(viewId: String) {
+    override fun sendMetric(viewId: String, viewDurationNs: Long) {
         val telemetry = viewTelemetry.remove(viewId)
         if (telemetry == null) {
             internalLogger.log(
@@ -69,24 +77,30 @@ internal class DefaultUISlownessMetricDispatcher(
             messageBuilder = { UI_SLOWNESS_MESSAGE },
             additionalProperties = buildMetricAttributesMap(
                 slowFramesCount = telemetry.slowFramesCount.get(),
-                ignoredFramesCount = telemetry.ignoredFramesCount.get()
+                ignoredFramesCount = telemetry.ignoredFramesCount.get(),
+                missedFramesCount = telemetry.missedFrameCount.get(),
+                viewDurationNs = viewDurationNs
             )
         )
     }
 
     private fun buildMetricAttributesMap(
         slowFramesCount: Int,
-        ignoredFramesCount: Int
+        ignoredFramesCount: Int,
+        missedFramesCount: Int,
+        viewDurationNs: Long
     ): Map<String, Any> = buildMap {
         put(KEY_METRIC_TYPE, VALUE_METRIC_TYPE)
         put(
             KEY_RUM_UI_SLOWNESS,
             buildMap {
+                put(KEY_VIEW_DURATION, viewDurationNs)
                 put(
                     KEY_SLOW_FRAMES,
                     buildMap {
                         put(KEY_COUNT, slowFramesCount)
                         put(KEY_IGNORED_COUNT, ignoredFramesCount)
+                        put(KEY_MISSED_COUNT, missedFramesCount)
                         put(
                             KEY_CONFIG,
                             buildMap {
@@ -114,7 +128,9 @@ internal class DefaultUISlownessMetricDispatcher(
 
         internal const val KEY_SLOW_FRAMES = "slow_frames"
         internal const val KEY_COUNT = "count"
+        internal const val KEY_VIEW_DURATION = "view_duration"
         internal const val KEY_IGNORED_COUNT = "ignored_count"
+        internal const val KEY_MISSED_COUNT = "missed_count"
         internal const val KEY_CONFIG = "config"
         internal const val KEY_MAX_COUNT = "max_count"
         internal const val KEY_SLOW_FRAME_THRESHOLD = "slow_frame_threshold"

features/dd-sdk-android-rum/src/test/kotlin/com/datadog/android/rum/internal/domain/scope/RumApplicationScopeTest.kt

@@ -131,7 +131,7 @@ internal class RumApplicationScopeTest {
         whenever(mockSdkCore.getFeature(Feature.RUM_FEATURE_NAME)) doReturn mockRumFeatureScope
         whenever(mockSdkCore.time) doReturn fakeTimeInfoAtScopeStart
         whenever(mockSdkCore.internalLogger) doReturn mock()
-        whenever(mockSlowFramesListener.resolveReport(any(), any())) doReturn viewUIPerformanceReport
+        whenever(mockSlowFramesListener.resolveReport(any(), any(), any())) doReturn viewUIPerformanceReport
 
         testedScope = RumApplicationScope(
             fakeApplicationId,

features/dd-sdk-android-rum/src/test/kotlin/com/datadog/android/rum/internal/domain/scope/RumRawEventExt.kt

@@ -26,10 +26,11 @@ internal fun Forge.interactiveRumRawEvent(): RumRawEvent {
     )
 }
 
-internal fun Forge.startViewEvent(): RumRawEvent.StartView {
+internal fun Forge.startViewEvent(eventTime: Time = Time()): RumRawEvent.StartView {
     return RumRawEvent.StartView(
         key = getForgery(),
-        attributes = exhaustiveAttributes()
+        attributes = exhaustiveAttributes(),
+        eventTime = eventTime
     )
 }
 

features/dd-sdk-android-rum/src/test/kotlin/com/datadog/android/rum/internal/domain/scope/RumViewManagerScopeTest.kt

@@ -144,7 +144,7 @@ internal class RumViewManagerScopeTest {
         whenever(mockChildScope.handleEvent(any(), any())) doReturn mockChildScope
         whenever(mockChildScope.isActive()) doReturn true
         whenever(mockSdkCore.internalLogger) doReturn mockInternalLogger
-        whenever(mockSlowFramesListener.resolveReport(any(), any())) doReturn fakeViewUIPerformanceReport
+        whenever(mockSlowFramesListener.resolveReport(any(), any(), any())) doReturn fakeViewUIPerformanceReport
 
         testedScope = RumViewManagerScope(
             mockParentScope,

features/dd-sdk-android-rum/src/test/kotlin/com/datadog/android/rum/internal/domain/scope/RumViewScopeTest.kt

@@ -234,6 +234,9 @@ internal class RumViewScopeTest {
     @BoolForgery
     var fakeTrackFrustrations: Boolean = true
 
+    @LongForgery(min = 1L)
+    var fakeViewDurationNs: Long = 0
+
     lateinit var fakeReplayStats: ViewEvent.ReplayStats
 
     private var fakeSampleRate: Float = 0.0f
@@ -326,7 +329,7 @@ internal class RumViewScopeTest {
             }
             .toEvictingQueue()
 
-        whenever(mockSlowFramesListener.resolveReport(any(), any())) doReturn mockViewUIPerformanceReport
+        whenever(mockSlowFramesListener.resolveReport(any(), any(), any())) doReturn mockViewUIPerformanceReport
         whenever(mockParentScope.getRumContext()) doReturn fakeParentContext
         whenever(mockChildScope.handleEvent(any(), any())) doReturn mockChildScope
         whenever(mockActionScope.handleEvent(any(), any())) doReturn mockActionScope
@@ -9626,33 +9629,43 @@ internal class RumViewScopeTest {
         forge: Forge
     ) {
         // Given
-        fakeEvent = RumRawEvent.StopView(key = testedScope.key, forge.exhaustiveAttributes())
+        fakeEvent = RumRawEvent.StopView(
+            key = testedScope.key,
+            attributes = forge.exhaustiveAttributes(),
+            eventTime = Time(nanoTime = fakeEventTime.nanoTime + fakeViewDurationNs)
+        )
 
         // When
         testedScope.handleEvent(fakeEvent, mockWriter)
 
         // Then
-        verify(mockSlowFramesListener).resolveReport(testedScope.viewId, true)
+        verify(mockSlowFramesListener).resolveReport(testedScope.viewId, true, fakeViewDurationNs)
     }
 
     @Test
     fun `M call resolveReport(viewId, true) of slowFramesListener W handleEvent(StartView)`(
         forge: Forge
     ) {
         // When
-        testedScope.handleEvent(forge.startViewEvent(), mockWriter)
+        testedScope.handleEvent(
+            forge.startViewEvent(eventTime = Time(nanoTime = fakeEventTime.nanoTime + fakeViewDurationNs)),
+            mockWriter
+        )
 
         // Then
-        verify(mockSlowFramesListener).resolveReport(testedScope.viewId, true)
+        verify(mockSlowFramesListener).resolveReport(testedScope.viewId, true, fakeViewDurationNs)
     }
 
     @Test
-    fun `M call resolveReport(viewId, true) of slowFramesListener W handleEvent(StopSession)`() {
+    fun `M call resolveReport(viewId, true, Long) of slowFramesListener W handleEvent(StopSession)`() {
         // When
-        testedScope.handleEvent(RumRawEvent.StopSession(), mockWriter)
+        testedScope.handleEvent(
+            RumRawEvent.StopSession(eventTime = Time(nanoTime = fakeEventTime.nanoTime + fakeViewDurationNs)),
+            mockWriter
+        )
 
         // Then
-        verify(mockSlowFramesListener).resolveReport(testedScope.viewId, true)
+        verify(mockSlowFramesListener).resolveReport(testedScope.viewId, true, fakeViewDurationNs)
     }
 
     @Test
@@ -9675,7 +9688,7 @@ internal class RumViewScopeTest {
         testedScope.handleEvent(event, mockWriter)
 
         // Then
-        verify(mockSlowFramesListener).resolveReport(testedScope.viewId, false)
+        verify(mockSlowFramesListener).resolveReport(eq(testedScope.viewId), eq(false), any())
     }
 
     // endregion