Fix TTFD measurement when API called too early

CHANGELOG.md

@@ -22,6 +22,7 @@
 
 ### Fixes
 
+- Fix TTFD measurement when API called too early ([#4297](https://github.com/getsentry/sentry-java/pull/4297))
 - Do not override user-defined `SentryOptions` ([#4262](https://github.com/getsentry/sentry-java/pull/4262))
 - Session Replay: Change bitmap config to `ARGB_8888` for screenshots ([#4282](https://github.com/getsentry/sentry-java/pull/4282))
 - The `MANIFEST.MF` of `sentry-opentelemetry-agent` now has `Implementation-Version` set to the raw version ([#4291](https://github.com/getsentry/sentry-java/pull/4291))

sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java

@@ -91,6 +91,9 @@ public final class ActivityLifecycleIntegration
 
   private final @NotNull ActivityFramesTracker activityFramesTracker;
   private final @NotNull AutoClosableReentrantLock lock = new AutoClosableReentrantLock();
+  private boolean fullyDisplayedCalled = false;
+  private final @NotNull AutoClosableReentrantLock fullyDisplayedLock =
+      new AutoClosableReentrantLock();
 
   public ActivityLifecycleIntegration(
       final @NotNull Application application,
@@ -413,12 +416,17 @@ public void onActivityCreated(
         scopes.configureScope(scope -> scope.setScreen(activityClassName));
       }
       startTracing(activity);
+      final @Nullable ISpan ttidSpan = ttidSpanMap.get(activity);
       final @Nullable ISpan ttfdSpan = ttfdSpanMap.get(activity);
 
       firstActivityCreated = true;
 
-      if (performanceEnabled && ttfdSpan != null && fullyDisplayedReporter != null) {
-        fullyDisplayedReporter.registerFullyDrawnListener(() -> onFullFrameDrawn(ttfdSpan));
+      if (performanceEnabled
+          && ttidSpan != null
+          && ttfdSpan != null
+          && fullyDisplayedReporter != null) {
+        fullyDisplayedReporter.registerFullyDrawnListener(
+            () -> onFullFrameDrawn(ttidSpan, ttfdSpan));
       }
     }
   }
@@ -635,37 +643,59 @@ private void onFirstFrameDrawn(final @Nullable ISpan ttfdSpan, final @Nullable I
     }
     finishAppStartSpan();
 
-    if (options != null && ttidSpan != null) {
-      final SentryDate endDate = options.getDateProvider().now();
-      final long durationNanos = endDate.diff(ttidSpan.getStartDate());
-      final long durationMillis = TimeUnit.NANOSECONDS.toMillis(durationNanos);
-      ttidSpan.setMeasurement(
-          MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY, durationMillis, MILLISECOND);
-
-      if (ttfdSpan != null && ttfdSpan.isFinished()) {
-        ttfdSpan.updateEndDate(endDate);
-        // If the ttfd span was finished before the first frame we adjust the measurement, too
+    // Sentry.reportFullyDisplayed can be run in any thread, so we have to ensure synchronization
+    // with first frame drawn
+    try (final @NotNull ISentryLifecycleToken ignored = fullyDisplayedLock.acquire()) {
+      if (options != null && ttidSpan != null) {
+        final SentryDate endDate = options.getDateProvider().now();
+        final long durationNanos = endDate.diff(ttidSpan.getStartDate());
+        final long durationMillis = TimeUnit.NANOSECONDS.toMillis(durationNanos);
         ttidSpan.setMeasurement(
-            MeasurementValue.KEY_TIME_TO_FULL_DISPLAY, durationMillis, MILLISECOND);
+            MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY, durationMillis, MILLISECOND);
+
+        // If the ttfd API was called before the first frame we finish the ttfd now
+        if (ttfdSpan != null && fullyDisplayedCalled) {
+          fullyDisplayedCalled = false;
+          ttidSpan.setMeasurement(
+              MeasurementValue.KEY_TIME_TO_FULL_DISPLAY, durationMillis, MILLISECOND);
+          ttfdSpan.setMeasurement(
+              MeasurementValue.KEY_TIME_TO_FULL_DISPLAY, durationMillis, MILLISECOND);
+          finishSpan(ttfdSpan, endDate);
+        }
+
+        finishSpan(ttidSpan, endDate);
+      } else {
+        finishSpan(ttidSpan);
+        if (fullyDisplayedCalled) {
+          finishSpan(ttfdSpan);
+        }
       }
-      finishSpan(ttidSpan, endDate);
-    } else {
-      finishSpan(ttidSpan);
     }
   }
 
-  private void onFullFrameDrawn(final @Nullable ISpan ttfdSpan) {
-    if (options != null && ttfdSpan != null) {
-      final SentryDate endDate = options.getDateProvider().now();
-      final long durationNanos = endDate.diff(ttfdSpan.getStartDate());
-      final long durationMillis = TimeUnit.NANOSECONDS.toMillis(durationNanos);
-      ttfdSpan.setMeasurement(
-          MeasurementValue.KEY_TIME_TO_FULL_DISPLAY, durationMillis, MILLISECOND);
-      finishSpan(ttfdSpan, endDate);
-    } else {
-      finishSpan(ttfdSpan);
-    }
+  private void onFullFrameDrawn(final @NotNull ISpan ttidSpan, final @NotNull ISpan ttfdSpan) {
     cancelTtfdAutoClose();
+    // Sentry.reportFullyDisplayed can be run in any thread, so we have to ensure synchronization
+    // with first frame drawn
+    try (final @NotNull ISentryLifecycleToken ignored = fullyDisplayedLock.acquire()) {
+      // If the TTID span didn't finish, it means the first frame was not drawn yet, which means
+      // Sentry.reportFullyDisplayed was called too early. We set a flag, so that whenever the TTID
+      // will finish, we will finish the TTFD span as well.
+      if (!ttidSpan.isFinished()) {
+        fullyDisplayedCalled = true;
+        return;
+      }
+      if (options != null) {
+        final SentryDate endDate = options.getDateProvider().now();
+        final long durationNanos = endDate.diff(ttfdSpan.getStartDate());
+        final long durationMillis = TimeUnit.NANOSECONDS.toMillis(durationNanos);
+        ttfdSpan.setMeasurement(
+            MeasurementValue.KEY_TIME_TO_FULL_DISPLAY, durationMillis, MILLISECOND);
+        finishSpan(ttfdSpan, endDate);
+      } else {
+        finishSpan(ttfdSpan);
+      }
+    }
   }
 
   private void finishExceededTtfdSpan(

sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt

@@ -54,6 +54,7 @@ import org.robolectric.shadow.api.Shadow
 import org.robolectric.shadows.ShadowActivityManager
 import java.util.Date
 import java.util.concurrent.Future
+import java.util.concurrent.TimeUnit
 import kotlin.test.AfterTest
 import kotlin.test.BeforeTest
 import kotlin.test.Test
@@ -300,7 +301,7 @@ class ActivityLifecycleIntegrationTest {
         val sut = fixture.getSut(initializer = {
             it.tracesSampleRate = 1.0
             it.isEnableTimeToFullDisplayTracing = true
-            it.idleTimeout = 200
+            it.idleTimeout = 100
         })
         sut.register(fixture.scopes, fixture.options)
         sut.onActivityCreated(activity, fixture.bundle)
@@ -318,7 +319,7 @@ class ActivityLifecycleIntegrationTest {
             )
 
         // but when idle timeout has passed
-        Thread.sleep(400)
+        Thread.sleep(200)
 
         // then the transaction should be finished
         verify(fixture.scopes).captureTransaction(
@@ -815,7 +816,6 @@ class ActivityLifecycleIntegrationTest {
 
         // when activity is resumed
         sut.onActivityResumed(activity)
-        Thread.sleep(1)
         runFirstDraw(view)
         // end-time should be set
         assertTrue(AppStartMetrics.getInstance().sdkInitTimeSpan.hasStopped())
@@ -863,17 +863,14 @@ class ActivityLifecycleIntegrationTest {
         sut.onActivityCreated(activity, fixture.bundle)
         sut.onActivityStarted(activity)
         sut.onActivityResumed(activity)
-        Thread.sleep(1)
         runFirstDraw(view)
 
         val firstAppStartEndTime = AppStartMetrics.getInstance().sdkInitTimeSpan.projectedStopTimestamp
 
-        Thread.sleep(1)
         sut.onActivityPaused(activity)
         sut.onActivityStopped(activity)
         sut.onActivityStarted(activity)
         sut.onActivityResumed(activity)
-        Thread.sleep(1)
         runFirstDraw(view)
 
         // then the end time should not be overwritten
@@ -983,6 +980,36 @@ class ActivityLifecycleIntegrationTest {
         )
     }
 
+    @Test
+    fun `When isEnableTimeToFullDisplayTracing is true and reportFullyDrawn is called, ttfd is finished on first frame if ttid is running`() {
+        val sut = fixture.getSut()
+        val view = fixture.createView()
+        val activity = mock<Activity>()
+        whenever(activity.findViewById<View>(any())).thenReturn(view)
+        fixture.options.tracesSampleRate = 1.0
+        fixture.options.isEnableTimeToFullDisplayTracing = true
+        sut.register(fixture.scopes, fixture.options)
+        sut.onActivityCreated(activity, fixture.bundle)
+        sut.onActivityResumed(activity)
+        val ttidSpan = sut.ttidSpanMap[activity]
+        val ttfdSpan = sut.ttfdSpanMap[activity]
+
+        // Assert the ttfd span is running and a timeout autoCancel future has been scheduled
+        assertNotNull(ttidSpan)
+        assertNotNull(ttfdSpan)
+        assertFalse(ttidSpan.isFinished)
+        assertFalse(ttfdSpan.isFinished)
+
+        // ReportFullyDrawn should not finish the ttfd span, as the ttid is still running
+        fixture.options.fullyDisplayedReporter.reportFullyDrawn()
+        assertFalse(ttfdSpan.isFinished)
+
+        // But when ReportFullyDrawn should not finish the ttfd span, as the ttid is still running
+        runFirstDraw(view)
+        assertTrue(ttidSpan.isFinished)
+        assertTrue(ttfdSpan.isFinished)
+    }
+
     @Test
     fun `When isEnableTimeToFullDisplayTracing is true and reportFullyDrawn is called, ttfd autoClose future is cancelled`() {
         val sut = fixture.getSut()
@@ -991,16 +1018,17 @@ class ActivityLifecycleIntegrationTest {
         sut.register(fixture.scopes, fixture.options)
         val activity = mock<Activity>()
         sut.onActivityCreated(activity, fixture.bundle)
+        val ttidSpan = sut.ttidSpanMap[activity]
         val ttfdSpan = sut.ttfdSpanMap[activity]
         var autoCloseFuture = sut.getProperty<Future<*>?>("ttfdAutoCloseFuture")
+        ttidSpan?.finish()
 
         // Assert the ttfd span is running and a timeout autoCancel future has been scheduled
         assertNotNull(ttfdSpan)
         assertFalse(ttfdSpan.isFinished)
         assertNotNull(autoCloseFuture)
 
         // ReportFullyDrawn should finish the ttfd span and cancel the future
-        Thread.sleep(1)
         fixture.options.fullyDisplayedReporter.reportFullyDrawn()
         assertTrue(ttfdSpan.isFinished)
         assertNotEquals(SpanStatus.DEADLINE_EXCEEDED, ttfdSpan.status)
@@ -1077,7 +1105,6 @@ class ActivityLifecycleIntegrationTest {
         assertFalse(ttidSpan.isFinished)
 
         // Mock the draw of the view. The ttid span should finish now
-        Thread.sleep(1)
         runFirstDraw(view)
         assertTrue(ttidSpan.isFinished)
 
@@ -1097,7 +1124,9 @@ class ActivityLifecycleIntegrationTest {
 
     @Test
     fun `When isEnableTimeToFullDisplayTracing is true and reportFullyDrawn is called too early, ttfd is adjusted to equal ttid`() {
-        val sut = fixture.getSut()
+        val sut = fixture.getSut() {
+//            it.fullyDisplayedReporter = mock()
+        }
         val view = fixture.createView()
         val activity = mock<Activity>()
         fixture.options.tracesSampleRate = 1.0
@@ -1116,18 +1145,28 @@ class ActivityLifecycleIntegrationTest {
         assertFalse(ttfdSpan.isFinished)
 
         // Let's finish the ttfd span too early (before the first view is drawn)
-        ttfdSpan.finish()
-        assertTrue(ttfdSpan.isFinished)
-        val oldEndDate = ttfdSpan.finishDate
+        fixture.options.fullyDisplayedReporter.reportFullyDrawn()
 
-        // Mock the draw of the view. The ttid span should finish now and the ttfd end date should be adjusted
+        // The TTFD shouldn't be finished yet
+        assertFalse(ttfdSpan.isFinished)
+
+        // Mock the draw of the view. The ttid span should finish now and the ttfd, too
         runFirstDraw(view)
         assertTrue(ttidSpan.isFinished)
-        val newEndDate = ttfdSpan.finishDate
-        assertNotEquals(newEndDate, oldEndDate)
-        assertEquals(newEndDate, ttidSpan.finishDate)
+        assertTrue(ttfdSpan.isFinished)
+        assertEquals(ttfdSpan.finishDate, ttidSpan.finishDate)
 
         sut.onActivityDestroyed(activity)
+
+        // The measurements should be set to the same value for ttid and ttfd
+        val ttidDuration = TimeUnit.NANOSECONDS.toMillis(ttidSpan.finishDate!!.diff(ttidSpan.startDate))
+        val ttfdDuration = TimeUnit.NANOSECONDS.toMillis(ttfdSpan.finishDate!!.diff(ttfdSpan.startDate))
+        assertEquals(ttidDuration, ttfdDuration)
+        // TTID also has initial display measurement, but TTFD has not
+        assertEquals(ttidDuration, ttidSpan.measurements[MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY]!!.value)
+        assertEquals(ttidDuration, ttidSpan.measurements[MeasurementValue.KEY_TIME_TO_FULL_DISPLAY]!!.value)
+        assertEquals(ttidDuration, ttfdSpan.measurements[MeasurementValue.KEY_TIME_TO_FULL_DISPLAY]!!.value)
+
         verify(fixture.scopes).captureTransaction(
             check {
                 // ttid and ttfd measurements should be the same
@@ -1189,7 +1228,6 @@ class ActivityLifecycleIntegrationTest {
         assertFalse(ttfdSpan.isFinished)
 
         // Run the autoClose task 1 ms after finishing the ttid span and assert the ttfd span is finished
-        Thread.sleep(1)
         deferredExecutorService.runAll()
         assertTrue(ttfdSpan.isFinished)