diff --git a/CHANGELOG.md b/CHANGELOG.md index a169005898..6e13a3a6b5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,7 @@ ## Fixes - Fix crash on double SDK init ([#2679](https://github.com/getsentry/sentry-java/pull/2679)) +- Track a ttfd span per Activity ([#2673](https://github.com/getsentry/sentry-java/pull/2673)) ## 6.18.0 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 b0bb8fa3b0..f2717b4324 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 @@ -71,9 +71,9 @@ public final class ActivityLifecycleIntegration private @Nullable FullyDisplayedReporter fullyDisplayedReporter = null; private @Nullable ISpan appStartSpan; private final @NotNull WeakHashMap ttidSpanMap = new WeakHashMap<>(); + private final @NotNull WeakHashMap ttfdSpanMap = new WeakHashMap<>(); private @NotNull SentryDate lastPausedTime = AndroidDateUtils.getCurrentSentryDateTime(); private final @NotNull Handler mainHandler = new Handler(Looper.getMainLooper()); - private @Nullable ISpan ttfdSpan = null; private @Nullable Future ttfdAutoCloseFuture = null; // WeakHashMap isn't thread safe but ActivityLifecycleCallbacks is only called from the @@ -169,7 +169,8 @@ private void stopPreviousTransactions() { activitiesWithOngoingTransactions.entrySet()) { final ITransaction transaction = entry.getValue(); final ISpan ttidSpan = ttidSpanMap.get(entry.getKey()); - finishTransaction(transaction, ttidSpan, true); + final ISpan ttfdSpan = ttfdSpanMap.get(entry.getKey()); + finishTransaction(transaction, ttidSpan, ttfdSpan); } } @@ -241,21 +242,21 @@ private void startTracing(final @NotNull Activity activity) { // we can finish the app-start span finishAppStartSpan(); } - ttidSpanMap.put( - activity, + final @NotNull ISpan ttidSpan = transaction.startChild( - TTID_OP, getTtidDesc(activityName), ttidStartTime, Instrumenter.SENTRY)); + TTID_OP, getTtidDesc(activityName), ttidStartTime, Instrumenter.SENTRY); + ttidSpanMap.put(activity, ttidSpan); if (timeToFullDisplaySpanEnabled && fullyDisplayedReporter != null && options != null) { - ttfdSpan = + final @NotNull ISpan ttfdSpan = transaction.startChild( TTFD_OP, getTtfdDesc(activityName), ttidStartTime, Instrumenter.SENTRY); try { + ttfdSpanMap.put(activity, ttfdSpan); ttfdAutoCloseFuture = options .getExecutorService() - .schedule( - () -> finishExceededTtfdSpan(ttidSpanMap.get(activity)), TTFD_TIMEOUT_MILLIS); + .schedule(() -> finishExceededTtfdSpan(ttfdSpan, ttidSpan), TTFD_TIMEOUT_MILLIS); } catch (RejectedExecutionException e) { options .getLogger() @@ -312,14 +313,14 @@ private boolean isRunningTransaction(final @NotNull Activity activity) { private void stopTracing(final @NotNull Activity activity, final boolean shouldFinishTracing) { if (performanceEnabled && shouldFinishTracing) { final ITransaction transaction = activitiesWithOngoingTransactions.get(activity); - finishTransaction(transaction, null, false); + finishTransaction(transaction, null, null); } } private void finishTransaction( final @Nullable ITransaction transaction, final @Nullable ISpan ttidSpan, - final boolean finishTtfd) { + final @Nullable ISpan ttfdSpan) { if (transaction != null) { // if io.sentry.traces.activity.auto-finish.enable is disabled, transaction may be already // finished manually when this method is called. @@ -329,9 +330,7 @@ private void finishTransaction( // in case the ttidSpan isn't completed yet, we finish it as cancelled to avoid memory leak finishSpan(ttidSpan, SpanStatus.DEADLINE_EXCEEDED); - if (finishTtfd) { - finishExceededTtfdSpan(ttidSpan); - } + finishExceededTtfdSpan(ttfdSpan, ttidSpan); cancelTtfdAutoClose(); SpanStatus status = transaction.getStatus(); @@ -357,11 +356,12 @@ public synchronized void onActivityCreated( setColdStart(savedInstanceState); addBreadcrumb(activity, "created"); startTracing(activity); + final @Nullable ISpan ttfdSpan = ttfdSpanMap.get(activity); firstActivityCreated = true; if (fullyDisplayedReporter != null) { - fullyDisplayedReporter.registerFullyDrawnListener(() -> onFullFrameDrawn()); + fullyDisplayedReporter.registerFullyDrawnListener(() -> onFullFrameDrawn(ttfdSpan)); } } @@ -392,16 +392,17 @@ public synchronized void onActivityResumed(final @NotNull Activity activity) { } finishAppStartSpan(); - final ISpan ttidSpan = ttidSpanMap.get(activity); + final @Nullable ISpan ttidSpan = ttidSpanMap.get(activity); + final @Nullable ISpan ttfdSpan = ttfdSpanMap.get(activity); final View rootView = activity.findViewById(android.R.id.content); if (buildInfoProvider.getSdkInfoVersion() >= Build.VERSION_CODES.JELLY_BEAN && rootView != null) { FirstDrawDoneListener.registerForNextDraw( - rootView, () -> onFirstFrameDrawn(ttidSpan), buildInfoProvider); + rootView, () -> onFirstFrameDrawn(ttfdSpan, ttidSpan), buildInfoProvider); } else { // Posting a task to the main thread's handler will make it executed after it finished // its current job. That is, right after the activity draws the layout. - mainHandler.post(() -> onFirstFrameDrawn(ttidSpan)); + mainHandler.post(() -> onFirstFrameDrawn(ttfdSpan, ttidSpan)); } addBreadcrumb(activity, "resumed"); } @@ -457,10 +458,11 @@ public synchronized void onActivityDestroyed(final @NotNull Activity activity) { // we finish the ttidSpan as cancelled in case it isn't completed yet final ISpan ttidSpan = ttidSpanMap.get(activity); + final ISpan ttfdSpan = ttfdSpanMap.get(activity); finishSpan(ttidSpan, SpanStatus.DEADLINE_EXCEEDED); // we finish the ttfdSpan as deadline_exceeded in case it isn't completed yet - finishExceededTtfdSpan(ttidSpan); + finishExceededTtfdSpan(ttfdSpan, ttidSpan); cancelTtfdAutoClose(); // in case people opt-out enableActivityLifecycleTracingAutoFinish and forgot to finish it, @@ -470,7 +472,7 @@ public synchronized void onActivityDestroyed(final @NotNull Activity activity) { // set it to null in case its been just finished as cancelled appStartSpan = null; ttidSpanMap.remove(activity); - ttfdSpan = null; + ttfdSpanMap.remove(activity); // clear it up, so we don't start again for the same activity if the activity is in the activity // stack still. @@ -516,7 +518,7 @@ private void cancelTtfdAutoClose() { } } - private void onFirstFrameDrawn(final @Nullable ISpan ttidSpan) { + private void onFirstFrameDrawn(final @Nullable ISpan ttfdSpan, final @Nullable ISpan ttidSpan) { if (options != null && ttidSpan != null) { final SentryDate endDate = options.getDateProvider().now(); final long durationNanos = endDate.diff(ttidSpan.getStartDate()); @@ -536,7 +538,7 @@ private void onFirstFrameDrawn(final @Nullable ISpan ttidSpan) { } } - private void onFullFrameDrawn() { + 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()); @@ -550,12 +552,13 @@ private void onFullFrameDrawn() { cancelTtfdAutoClose(); } - private void finishExceededTtfdSpan(final @Nullable ISpan ttidSpan) { - if (ttfdSpan == null) { + private void finishExceededTtfdSpan( + final @Nullable ISpan ttfdSpan, final @Nullable ISpan ttidSpan) { + if (ttfdSpan == null || ttfdSpan.isFinished()) { return; } ttfdSpan.setDescription(getExceededTtfdDesc(ttfdSpan)); - // We set the end timestamp of the ttfd span to be equal to the ttid span. This way, + // We set the end timestamp of the ttfd span to be equal to the ttid span. final @Nullable SentryDate ttidEndDate = ttidSpan != null ? ttidSpan.getFinishDate() : null; final @NotNull SentryDate ttfdEndDate = ttidEndDate != null ? ttidEndDate : ttfdSpan.getStartDate(); @@ -587,9 +590,9 @@ WeakHashMap getTtidSpanMap() { } @TestOnly - @Nullable - ISpan getTtfdSpan() { - return ttfdSpan; + @NotNull + WeakHashMap getTtfdSpanMap() { + return ttfdSpanMap; } private void setColdStart(final @Nullable Bundle savedInstanceState) { 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 1cdfbc3fc3..ce66f1dcc7 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 @@ -452,7 +452,7 @@ class ActivityLifecycleIntegrationTest { sut.onActivityCreated(activity, fixture.bundle) sut.ttidSpanMap.values.first().finish() - sut.ttfdSpan?.finish() + sut.ttfdSpanMap.values.first().finish() // then transaction should not be immediatelly finished verify(fixture.hub, never()) @@ -678,10 +678,10 @@ class ActivityLifecycleIntegrationTest { val activity = mock() sut.onActivityCreated(activity, fixture.bundle) - assertNotNull(sut.ttfdSpan) + assertNotNull(sut.ttfdSpanMap[activity]) sut.onActivityDestroyed(activity) - assertNull(sut.ttfdSpan) + assertNull(sut.ttfdSpanMap[activity]) } @Test @@ -719,7 +719,7 @@ class ActivityLifecycleIntegrationTest { val activity = mock() sut.onActivityCreated(activity, mock()) sut.ttidSpanMap.values.first().finish() - sut.ttfdSpan?.finish() + sut.ttfdSpanMap.values.first().finish() sut.onActivityResumed(activity) verify(fixture.hub, never()).captureTransaction(any(), any(), anyOrNull(), anyOrNull()) @@ -748,7 +748,7 @@ class ActivityLifecycleIntegrationTest { val activity = mock() sut.onActivityCreated(activity, mock()) - val ttfd = sut.ttfdSpan + val ttfd = sut.ttfdSpanMap[activity] sut.ttidSpanMap.values.first().finish() sut.onActivityResumed(activity) sut.onActivityPostResumed(activity) @@ -766,10 +766,11 @@ class ActivityLifecycleIntegrationTest { val activity = mock() sut.onActivityCreated(activity, mock()) + val ttfdSpan = sut.ttfdSpanMap[activity] sut.ttidSpanMap.values.first().finish() fixture.fullyDisplayedReporter.reportFullyDrawn() - assertTrue(sut.ttfdSpan!!.isFinished) - assertNotEquals(SpanStatus.CANCELLED, sut.ttfdSpan?.status) + assertTrue(ttfdSpan!!.isFinished) + assertNotEquals(SpanStatus.CANCELLED, ttfdSpan.status) } @Test @@ -1070,7 +1071,8 @@ class ActivityLifecycleIntegrationTest { val activity = mock() sut.onActivityCreated(activity, fixture.bundle) - assertNull(sut.ttfdSpan) + val ttfdSpan = sut.ttfdSpanMap[activity] + assertNull(ttfdSpan) } @Test @@ -1082,7 +1084,8 @@ class ActivityLifecycleIntegrationTest { val activity = mock() sut.onActivityCreated(activity, fixture.bundle) - assertNotNull(sut.ttfdSpan) + val ttfdSpan = sut.ttfdSpanMap[activity] + assertNotNull(ttfdSpan) } @Test @@ -1105,7 +1108,7 @@ class ActivityLifecycleIntegrationTest { sut.register(fixture.hub, fixture.options) val activity = mock() sut.onActivityCreated(activity, fixture.bundle) - val ttfdSpan = sut.ttfdSpan + val ttfdSpan = sut.ttfdSpanMap[activity] // Assert the ttfd span is running and a timeout autoCancel task has been scheduled assertNotNull(ttfdSpan) @@ -1138,7 +1141,7 @@ class ActivityLifecycleIntegrationTest { sut.register(fixture.hub, fixture.options) val activity = mock() sut.onActivityCreated(activity, fixture.bundle) - val ttfdSpan = sut.ttfdSpan + val ttfdSpan = sut.ttfdSpanMap[activity] var autoCloseFuture = sut.getProperty?>("ttfdAutoCloseFuture") // Assert the ttfd span is running and a timeout autoCancel future has been scheduled @@ -1181,7 +1184,7 @@ class ActivityLifecycleIntegrationTest { val activity2 = mock() sut.onActivityCreated(activity, fixture.bundle) sut.onActivityPostResumed(activity) - val ttfdSpan = sut.ttfdSpan + val ttfdSpan = sut.ttfdSpanMap[activity] val autoCloseFuture = sut.getProperty?>("ttfdAutoCloseFuture") // Assert the ttfd span is running and a timeout autoCancel future has been scheduled @@ -1197,7 +1200,7 @@ class ActivityLifecycleIntegrationTest { // Another autoClose future and ttfd span should be started after the second activity starts val autoCloseFuture2 = sut.getProperty?>("ttfdAutoCloseFuture") - val ttfdSpan2 = sut.ttfdSpan + val ttfdSpan2 = sut.ttfdSpanMap[activity2] assertNotNull(ttfdSpan2) assertFalse(ttfdSpan2.isFinished) assertNotNull(autoCloseFuture2) @@ -1258,7 +1261,7 @@ class ActivityLifecycleIntegrationTest { // The ttid and ttfd spans should be running val ttidSpan = sut.ttidSpanMap[activity] as Span - val ttfdSpan = sut.ttfdSpan as Span + val ttfdSpan = sut.ttfdSpanMap[activity] as Span assertFalse(ttidSpan.isFinished) assertFalse(ttfdSpan.isFinished) @@ -1302,10 +1305,12 @@ class ActivityLifecycleIntegrationTest { // The ttid span should be running val ttidSpan = sut.ttidSpanMap[activity] + val ttfdSpan = sut.ttfdSpanMap[activity] assertNotNull(ttidSpan) + assertNotNull(ttfdSpan) assertEquals(ttidSpan.startDate, fixture.transaction.startDate) - assertEquals(sut.ttfdSpan?.startDate, fixture.transaction.startDate) + assertEquals(ttfdSpan.startDate, fixture.transaction.startDate) } @Test @@ -1333,7 +1338,7 @@ class ActivityLifecycleIntegrationTest { runFirstDraw(view) val ttidSpan = sut.ttidSpanMap[activity] - val ttfdSpan = sut.ttfdSpan + val ttfdSpan = sut.ttfdSpanMap[activity] // The ttid should be finished assertNotNull(ttidSpan) @@ -1354,6 +1359,31 @@ class ActivityLifecycleIntegrationTest { assertEquals(ttfdSpan.description, "Activity full display - Deadline Exceeded") } + @Test + fun `ttfd span is running on new activity when previous finishes`() { + val sut = fixture.getSut() + val activity = mock() + val activity2 = mock() + fixture.options.tracesSampleRate = 1.0 + fixture.options.isEnableTimeToFullDisplayTracing = true + + sut.register(fixture.hub, fixture.options) + sut.onActivityCreated(activity, fixture.bundle) + val ttfdSpan = sut.ttfdSpanMap[activity] + assertNotNull(ttfdSpan) + assertFalse(ttfdSpan.isFinished) + sut.onActivityPaused(activity) + sut.onActivityCreated(activity2, fixture.bundle) + val ttfdSpan2 = sut.ttfdSpanMap[activity2] + sut.onActivityResumed(activity2) + sut.onActivityStopped(activity) + sut.onActivityDestroyed(activity) + assertNotNull(ttfdSpan2) + // The old ttfd is finished and the new one is running + assertTrue(ttfdSpan.isFinished) + assertFalse(ttfdSpan2.isFinished) + } + private fun runFirstDraw(view: View) { // Removes OnDrawListener in the next OnGlobalLayout after onDraw view.viewTreeObserver.dispatchOnDraw()