Fix Frame measurements in app start transactions (#3382)

* performance collectors are called independently from profiling (now transactions get frames measurements) * TimeSpan.getStartTimestamp is now a SentryNanotimeDate, to fix FrameMetricsCollector on app start transactions
getsentry · Apr 23, 2024 · a33b076 · a33b076
1 parent 0156268
commit a33b076
Show file tree

Hide file tree

Showing 8 changed files with 113 additions and 12 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -8,6 +8,7 @@
 
 ### Fixes
 
+- Fix Frame measurements in app start transactions ([#3382](https://github.com/getsentry/sentry-java/pull/3382))
 - Fix timing metric value different from span duration ([#3368](https://github.com/getsentry/sentry-java/pull/3368))
 
 ## 7.8.0

diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java b/sentry-android-core/src/main/java/io/sentry/android/core/SpanFrameMetricsCollector.java
@@ -7,6 +7,7 @@
 import io.sentry.NoOpTransaction;
 import io.sentry.SentryDate;
 import io.sentry.SentryNanotimeDate;
+import io.sentry.SentryTracer;
 import io.sentry.SpanDataConvention;
 import io.sentry.android.core.internal.util.SentryFrameMetricsCollector;
 import io.sentry.protocol.MeasurementValue;
@@ -135,11 +136,15 @@ private void captureFrameMetrics(@NotNull final ISpan span) {
         return;
       }
 
-      // ignore spans with no finish date
-      final @Nullable SentryDate spanFinishDate = span.getFinishDate();
+      // Ignore spans with no finish date, but SentryTracer is not finished when executing this
+      // callback, yet, so in that case we use the current timestamp.
+      final @Nullable SentryDate spanFinishDate =
+          span instanceof SentryTracer ? new SentryNanotimeDate() : span.getFinishDate();
       if (spanFinishDate == null) {
         return;
       }
+      // Note: The comparison between two values obtained by realNanos() works only if both are the
+      // same kind of dates (both are SentryNanotimeDate or both SentryLongDate)
       final long spanEndNanos = realNanos(spanFinishDate);
 
       final @NotNull SentryFrameMetrics frameMetrics = new SentryFrameMetrics();

diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/performance/TimeSpan.java b/sentry-android-core/src/main/java/io/sentry/android/core/performance/TimeSpan.java
@@ -4,6 +4,8 @@
 import io.sentry.DateUtils;
 import io.sentry.SentryDate;
 import io.sentry.SentryLongDate;
+import io.sentry.SentryNanotimeDate;
+import java.util.concurrent.TimeUnit;
 import org.jetbrains.annotations.ApiStatus;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
@@ -21,6 +23,7 @@ public class TimeSpan implements Comparable<TimeSpan> {
 
   private @Nullable String description;
 
+  private long startSystemNanos;
   private long startUnixTimeMs;
   private long startUptimeMs;
   private long stopUptimeMs;
@@ -29,6 +32,7 @@ public class TimeSpan implements Comparable<TimeSpan> {
   public void start() {
     startUptimeMs = SystemClock.uptimeMillis();
     startUnixTimeMs = System.currentTimeMillis();
+    startSystemNanos = System.nanoTime();
   }
 
   /**
@@ -40,6 +44,7 @@ public void setStartedAt(final long uptimeMs) {
 
     final long shiftMs = SystemClock.uptimeMillis() - startUptimeMs;
     startUnixTimeMs = System.currentTimeMillis() - shiftMs;
+    startSystemNanos = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos(shiftMs);
   }
 
   /** Stops the time span */
@@ -90,7 +95,8 @@ public long getStartTimestampMs() {
    */
   public @Nullable SentryDate getStartTimestamp() {
     if (hasStarted()) {
-      return new SentryLongDate(DateUtils.millisToNanos(getStartTimestampMs()));
+      return new SentryNanotimeDate(
+          DateUtils.nanosToDate(DateUtils.millisToNanos(getStartTimestampMs())), startSystemNanos);
     }
     return null;
   }
@@ -162,6 +168,7 @@ public void reset() {
     startUptimeMs = 0;
     stopUptimeMs = 0;
     startUnixTimeMs = 0;
+    startSystemNanos = 0;
   }
 
   @Override

diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/SpanFrameMetricsCollectorTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/SpanFrameMetricsCollectorTest.kt
@@ -40,9 +40,7 @@ class SpanFrameMetricsCollectorTest {
             options.frameMetricsCollector = frameMetricsCollector
             options.isEnableFramesTracking = enabled
             options.isEnablePerformanceV2 = enabled
-            options.setDateProvider {
-                SentryLongDate(timeNanos)
-            }
+            options.dateProvider = SentryAndroidDateProvider()
 
             return SpanFrameMetricsCollector(options, frameMetricsCollector)
         }

diff --git a/...sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/AutomaticSpansTest.kt b/...sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/AutomaticSpansTest.kt
@@ -2,13 +2,23 @@ package io.sentry.uitest.android
 
 import androidx.lifecycle.Lifecycle
 import androidx.test.core.app.launchActivity
+import androidx.test.espresso.Espresso
+import androidx.test.espresso.IdlingRegistry
+import androidx.test.espresso.action.ViewActions
+import androidx.test.espresso.matcher.ViewMatchers
 import androidx.test.ext.junit.runners.AndroidJUnit4
 import io.sentry.Sentry
 import io.sentry.SentryLevel
+import io.sentry.android.core.AndroidLogger
 import io.sentry.android.core.SentryAndroidOptions
+import io.sentry.assertEnvelopeTransaction
+import io.sentry.protocol.MeasurementValue
 import io.sentry.protocol.SentryTransaction
+import org.junit.Assume
 import org.junit.runner.RunWith
 import kotlin.test.Test
+import kotlin.test.assertEquals
+import kotlin.test.assertNotEquals
 import kotlin.test.assertTrue
 
 @RunWith(AndroidJUnit4::class)
@@ -49,4 +59,84 @@ class AutomaticSpansTest : BaseUiTest() {
             }
         }
     }
+
+    @Test
+    fun checkAppStartFramesMeasurements() {
+        initSentry(true) { options: SentryAndroidOptions ->
+            options.tracesSampleRate = 1.0
+            options.isEnableTimeToFullDisplayTracing = true
+            options.isEnablePerformanceV2 = false
+        }
+
+        IdlingRegistry.getInstance().register(ProfilingSampleActivity.scrollingIdlingResource)
+        val sampleScenario = launchActivity<ProfilingSampleActivity>()
+        swipeList(3)
+        Sentry.reportFullyDisplayed()
+        sampleScenario.moveToState(Lifecycle.State.DESTROYED)
+        IdlingRegistry.getInstance().unregister(ProfilingSampleActivity.scrollingIdlingResource)
+        relayIdlingResource.increment()
+
+        relay.assert {
+            findEnvelope {
+                assertEnvelopeTransaction(it.items.toList(), AndroidLogger()).transaction == "ProfilingSampleActivity"
+            }.assert {
+                val transactionItem: SentryTransaction = it.assertTransaction()
+                it.assertNoOtherItems()
+                val measurements = transactionItem.measurements
+                val frozenFrames = measurements[MeasurementValue.KEY_FRAMES_FROZEN]?.value?.toInt() ?: 0
+                val slowFrames = measurements[MeasurementValue.KEY_FRAMES_SLOW]?.value?.toInt() ?: 0
+                val totalFrames = measurements[MeasurementValue.KEY_FRAMES_TOTAL]?.value?.toInt() ?: 0
+                assertEquals("ProfilingSampleActivity", transactionItem.transaction)
+                // AGP matrix tests have no frames
+                Assume.assumeTrue(totalFrames > 0)
+                assertNotEquals(totalFrames, 0)
+                assertTrue(totalFrames > slowFrames + frozenFrames, "Expected total frames ($totalFrames) to be higher than the sum of slow ($slowFrames) and frozen ($frozenFrames) frames.")
+            }
+            assertNoOtherEnvelopes()
+        }
+    }
+
+    @Test
+    fun checkAppStartFramesMeasurementsPerfV2() {
+        initSentry(true) { options: SentryAndroidOptions ->
+            options.tracesSampleRate = 1.0
+            options.isEnableTimeToFullDisplayTracing = true
+            options.isEnablePerformanceV2 = true
+        }
+
+        IdlingRegistry.getInstance().register(ProfilingSampleActivity.scrollingIdlingResource)
+        val sampleScenario = launchActivity<ProfilingSampleActivity>()
+        swipeList(3)
+        Sentry.reportFullyDisplayed()
+        sampleScenario.moveToState(Lifecycle.State.DESTROYED)
+        IdlingRegistry.getInstance().unregister(ProfilingSampleActivity.scrollingIdlingResource)
+        relayIdlingResource.increment()
+
+        relay.assert {
+            findEnvelope {
+                assertEnvelopeTransaction(it.items.toList(), AndroidLogger()).transaction == "ProfilingSampleActivity"
+            }.assert {
+                val transactionItem: SentryTransaction = it.assertTransaction()
+                it.assertNoOtherItems()
+                val measurements = transactionItem.measurements
+                val frozenFrames = measurements[MeasurementValue.KEY_FRAMES_FROZEN]?.value?.toInt() ?: 0
+                val slowFrames = measurements[MeasurementValue.KEY_FRAMES_SLOW]?.value?.toInt() ?: 0
+                val totalFrames = measurements[MeasurementValue.KEY_FRAMES_TOTAL]?.value?.toInt() ?: 0
+                assertEquals("ProfilingSampleActivity", transactionItem.transaction)
+                // AGP matrix tests have no frames
+                Assume.assumeTrue(totalFrames > 0)
+                assertNotEquals(totalFrames, 0)
+                assertTrue(totalFrames > slowFrames + frozenFrames, "Expected total frames ($totalFrames) to be higher than the sum of slow ($slowFrames) and frozen ($frozenFrames) frames.")
+            }
+            assertNoOtherEnvelopes()
+        }
+    }
+
+    private fun swipeList(times: Int) {
+        repeat(times) {
+            Thread.sleep(100)
+            Espresso.onView(ViewMatchers.withId(R.id.profiling_sample_list)).perform(ViewActions.swipeUp())
+            Espresso.onIdle()
+        }
+    }
 }
diff --git a/...ests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/EnvelopeTests.kt b/...ests/sentry-uitest-android/src/androidTest/java/io/sentry/uitest/android/EnvelopeTests.kt
@@ -157,7 +157,7 @@ class EnvelopeTests : BaseUiTest() {
                     // Timestamps of measurements should differ at least 10 milliseconds from each other
                     (1 until values.size).forEach { i ->
                         assertTrue(
-                            values[i].relativeStartNs.toLong() > values[i - 1].relativeStartNs.toLong() + TimeUnit.MILLISECONDS.toNanos(
+                            values[i].relativeStartNs.toLong() >= values[i - 1].relativeStartNs.toLong() + TimeUnit.MILLISECONDS.toNanos(
                                 10
                             ),
                             "Measurement value timestamp for '$name' does not differ at least 10ms"

diff --git a/sentry/src/main/java/io/sentry/SentryTracer.java b/sentry/src/main/java/io/sentry/SentryTracer.java
@@ -87,9 +87,9 @@ public SentryTracer(
       this.baggage = new Baggage(hub.getOptions().getLogger());
     }
 
-    // We are currently sending the performance data only in profiles, so there's no point in
-    // collecting them if a profile is not sampled
-    if (transactionPerformanceCollector != null && Boolean.TRUE.equals(isProfileSampled())) {
+    // We are currently sending the performance data only in profiles, but we are always sending
+    // performance measurements.
+    if (transactionPerformanceCollector != null) {
       transactionPerformanceCollector.start(this);
     }
 

diff --git a/sentry/src/test/java/io/sentry/SentryTracerTest.kt b/sentry/src/test/java/io/sentry/SentryTracerTest.kt
@@ -1005,9 +1005,9 @@ class SentryTracerTest {
     }
 
     @Test
-    fun `when transaction is created, but not profiled, transactionPerformanceCollector is not started`() {
+    fun `when transaction is created, but not profiled, transactionPerformanceCollector is started anyway`() {
         val transaction = fixture.getSut()
-        verify(fixture.transactionPerformanceCollector, never()).start(anyOrNull())
+        verify(fixture.transactionPerformanceCollector).start(anyOrNull())
     }
 
     @Test