From 544da32844a71743db310ac0a126b0866344e18e Mon Sep 17 00:00:00 2001 From: Stefano Date: Fri, 28 Apr 2023 13:49:23 +0200 Subject: [PATCH] Track a ttfd span per Activity (#2673) * added map of ttfd spans in ActivityLifecycleIntegration, to automatically stop only the correct one --- CHANGELOG.md | 6 ++ .../core/ActivityLifecycleIntegration.java | 57 +++++++++-------- .../core/ActivityLifecycleIntegrationTest.kt | 62 ++++++++++++++----- 3 files changed, 82 insertions(+), 43 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 6ea74a7a04..321ed3ee32 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,11 @@ # Changelog +## Unreleased + +### Fixes + +- Track a ttfd span per Activity ([#2673](https://github.com/getsentry/sentry-java/pull/2673)) + ## 6.18.0 ### Features 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 8c20dce0ed..5c99612f8d 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 @@ -70,9 +70,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 @@ -168,7 +168,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); } } @@ -240,20 +241,20 @@ 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); + ttfdSpanMap.put(activity, ttfdSpan); ttfdAutoCloseFuture = options .getExecutorService() - .schedule( - () -> finishExceededTtfdSpan(ttidSpanMap.get(activity)), TTFD_TIMEOUT_MILLIS); + .schedule(() -> finishExceededTtfdSpan(ttfdSpan, ttidSpan), TTFD_TIMEOUT_MILLIS); } // lets bind to the scope so other integrations can pick it up @@ -302,14 +303,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. @@ -319,9 +320,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(); @@ -347,11 +346,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)); } } @@ -382,16 +382,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"); } @@ -447,10 +448,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, @@ -460,7 +462,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. @@ -506,7 +508,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()); @@ -526,7 +528,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()); @@ -540,12 +542,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(); @@ -577,9 +580,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 5ed4bd2bd7..c9b682bbfb 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 @@ -1104,7 +1107,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) @@ -1137,7 +1140,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 @@ -1180,7 +1183,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 @@ -1196,7 +1199,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) @@ -1257,7 +1260,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) @@ -1301,10 +1304,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 @@ -1331,7 +1336,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) @@ -1352,6 +1357,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()