From 2c44f516e727c8ae3744dd159aa3fc9ebb0dc45f Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Fri, 28 Mar 2025 16:20:13 +0100 Subject: [PATCH 1/4] Sentry.reportFullyDisplayed now sets a flag if the ttid is not finished. When the TTID finishes, if the flag is set, the TTFD is finished as well --- .../core/ActivityLifecycleIntegration.java | 84 +++++++++++++------ .../core/ActivityLifecycleIntegrationTest.kt | 72 ++++++++++++---- 2 files changed, 112 insertions(+), 44 deletions(-) diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java b/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java index 34d20cf455c..a0aa0dd1a81 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java +++ b/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( diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt index a3d5d99bf6a..06638d94765 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/ActivityLifecycleIntegrationTest.kt +++ b/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() + whenever(activity.findViewById(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,8 +1018,10 @@ class ActivityLifecycleIntegrationTest { sut.register(fixture.scopes, fixture.options) val activity = mock() sut.onActivityCreated(activity, fixture.bundle) + val ttidSpan = sut.ttidSpanMap[activity] val ttfdSpan = sut.ttfdSpanMap[activity] var autoCloseFuture = sut.getProperty?>("ttfdAutoCloseFuture") + ttidSpan?.finish() // Assert the ttfd span is running and a timeout autoCancel future has been scheduled assertNotNull(ttfdSpan) @@ -1000,7 +1029,6 @@ class ActivityLifecycleIntegrationTest { 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() 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) From 4d262fd7c8832f3297985e473eb91a284dccfc3d Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Fri, 28 Mar 2025 16:22:17 +0100 Subject: [PATCH 2/4] updated changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 4d136fd9c7a..ab90844e9fe 100644 --- a/CHANGELOG.md +++ b/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)) From 963adfa75b07ee21757188edcc16fe229dd3e77e Mon Sep 17 00:00:00 2001 From: stefanosiano Date: Tue, 15 Apr 2025 10:46:12 +0200 Subject: [PATCH 3/4] updated comment --- .../io/sentry/android/core/ActivityLifecycleIntegration.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java b/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java index a0aa0dd1a81..00f30fcacb9 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/ActivityLifecycleIntegration.java @@ -652,8 +652,8 @@ private void onFirstFrameDrawn(final @Nullable ISpan ttfdSpan, final @Nullable I final long durationMillis = TimeUnit.NANOSECONDS.toMillis(durationNanos); ttidSpan.setMeasurement( MeasurementValue.KEY_TIME_TO_INITIAL_DISPLAY, durationMillis, MILLISECOND); - - // If the ttfd API was called before the first frame we finish the ttfd now + // If Sentry.reportFullyDisplayed was called before the first frame is drawn, we finish + // the ttfd now if (ttfdSpan != null && fullyDisplayedCalled) { fullyDisplayedCalled = false; ttidSpan.setMeasurement( From f08a847f628943d33b029dad68b9c99709d1ab4f Mon Sep 17 00:00:00 2001 From: Stefano Date: Tue, 15 Apr 2025 10:47:25 +0200 Subject: [PATCH 4/4] Update CHANGELOG.md --- CHANGELOG.md | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index a520355d2ac..2889793e7e8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,11 @@ # Changelog +## Unreleased + +### Fixes + +- Fix TTFD measurement when API called too early ([#4297](https://github.com/getsentry/sentry-java/pull/4297)) + ## 8.8.0 ### Features @@ -98,7 +104,6 @@ ### 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))