diff --git a/CHANGELOG.md b/CHANGELOG.md index f7cafab10f..45d8b0873b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,7 @@ ### Fixes - Ignore Shutdown in progress when closing ShutdownHookIntegration ([#2521](https://github.com/getsentry/sentry-java/pull/2521)) +- Fix app start span end-time is wrong if SDK init is deferred ([#2519](https://github.com/getsentry/sentry-java/pull/2519)) ## 6.13.1 diff --git a/sentry-android-core/api/sentry-android-core.api b/sentry-android-core/api/sentry-android-core.api index 20ea1e97d9..8aa2350d0d 100644 --- a/sentry-android-core/api/sentry-android-core.api +++ b/sentry-android-core/api/sentry-android-core.api @@ -71,6 +71,7 @@ public final class io/sentry/android/core/AppLifecycleIntegration : io/sentry/In } public final class io/sentry/android/core/AppStartState { + public fun getAppStartEndTime ()Lio/sentry/SentryDate; public fun getAppStartInterval ()Ljava/lang/Long; public fun getAppStartMillis ()Ljava/lang/Long; public fun getAppStartTime ()Lio/sentry/SentryDate; 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 d448c92b21..4e00390771 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 @@ -56,8 +56,7 @@ public final class ActivityLifecycleIntegration private boolean isAllActivityCallbacksAvailable; private boolean firstActivityCreated = false; - private boolean firstActivityResumed = false; - private boolean foregroundImportance = false; + private final boolean foregroundImportance; private @Nullable ISpan appStartSpan; private final @NotNull WeakHashMap ttidSpanMap = new WeakHashMap<>(); @@ -210,6 +209,11 @@ private void startTracing(final @NotNull Activity activity) { getAppStartDesc(coldStart), appStartTime, Instrumenter.SENTRY); + + // in case there's already an end time (e.g. due to deferred SDK init) + // we can finish the app-start span + finishAppStartSpan(); + // The first activity ttidSpan should start at the same time as the app start time ttidSpanMap.put( activity, @@ -328,28 +332,17 @@ public synchronized void onActivityStarted(final @NotNull Activity activity) { @SuppressLint("NewApi") @Override public synchronized void onActivityResumed(final @NotNull Activity activity) { - if (!firstActivityResumed) { - - // we only finish the app start if the process is of foregroundImportance - if (foregroundImportance) { - // sets App start as finished when the very first activity calls onResume - AppStartState.getInstance().setAppStartEnd(); - } else { - if (options != null) { - options - .getLogger() - .log( - SentryLevel.DEBUG, - "App Start won't be reported because Process wasn't of foregroundImportance."); - } - } - // finishes app start span - if (performanceEnabled && appStartSpan != null) { - appStartSpan.finish(); - } - firstActivityResumed = true; + // app start span + @Nullable final SentryDate appStartStartTime = AppStartState.getInstance().getAppStartTime(); + @Nullable final SentryDate appStartEndTime = AppStartState.getInstance().getAppStartEndTime(); + // in case the SentryPerformanceProvider is disabled it does not set the app start times, + // and we need to set the end time manually here, + // the start time gets set manually in SentryAndroid.init() + if (appStartStartTime != null && appStartEndTime == null) { + AppStartState.getInstance().setAppStartEnd(); } + finishAppStartSpan(); final ISpan ttidSpan = ttidSpanMap.get(activity); final View rootView = activity.findViewById(android.R.id.content); @@ -507,4 +500,17 @@ private void setColdStart(final @Nullable Bundle savedInstanceState) { return APP_START_WARM; } } + + private void finishAppStartSpan() { + final @Nullable SentryDate appStartEndTime = AppStartState.getInstance().getAppStartEndTime(); + if (appStartSpan != null + && !appStartSpan.isFinished() + && performanceEnabled + && appStartEndTime != null) { + + final SpanStatus status = + appStartSpan.getStatus() != null ? appStartSpan.getStatus() : SpanStatus.OK; + appStartSpan.finish(status, appStartEndTime); + } + } } diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/AppStartState.java b/sentry-android-core/src/main/java/io/sentry/android/core/AppStartState.java index 27e2581e28..de690aa668 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/AppStartState.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/AppStartState.java @@ -1,7 +1,9 @@ package io.sentry.android.core; import android.os.SystemClock; +import io.sentry.DateUtils; import io.sentry.SentryDate; +import io.sentry.SentryLongDate; import org.jetbrains.annotations.ApiStatus; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; @@ -84,6 +86,20 @@ public SentryDate getAppStartTime() { return appStartTime; } + @Nullable + public SentryDate getAppStartEndTime() { + @Nullable final SentryDate start = getAppStartTime(); + if (start != null) { + @Nullable final Long durationMillis = getAppStartInterval(); + if (durationMillis != null) { + final long startNanos = start.nanoTimestamp(); + final long endNanos = startNanos + DateUtils.millisToNanos(durationMillis); + return new SentryLongDate(endNanos); + } + } + return null; + } + @Nullable public Long getAppStartMillis() { return appStartMillis; diff --git a/sentry-android-core/src/main/java/io/sentry/android/core/SentryPerformanceProvider.java b/sentry-android-core/src/main/java/io/sentry/android/core/SentryPerformanceProvider.java index ff94c61d36..7ba270351b 100644 --- a/sentry-android-core/src/main/java/io/sentry/android/core/SentryPerformanceProvider.java +++ b/sentry-android-core/src/main/java/io/sentry/android/core/SentryPerformanceProvider.java @@ -29,6 +29,8 @@ public final class SentryPerformanceProvider extends EmptySecureContentProvider private static long appStartMillis = SystemClock.uptimeMillis(); private boolean firstActivityCreated = false; + private boolean firstActivityResumed = false; + private @Nullable Application application; public SentryPerformanceProvider() { @@ -91,9 +93,6 @@ public void onActivityCreated(@NotNull Activity activity, @Nullable Bundle saved final boolean coldStart = savedInstanceState == null; AppStartState.getInstance().setColdStart(coldStart); - if (application != null) { - application.unregisterActivityLifecycleCallbacks(this); - } firstActivityCreated = true; } } @@ -102,7 +101,16 @@ public void onActivityCreated(@NotNull Activity activity, @Nullable Bundle saved public void onActivityStarted(@NotNull Activity activity) {} @Override - public void onActivityResumed(@NotNull Activity activity) {} + public void onActivityResumed(@NotNull Activity activity) { + if (!firstActivityResumed) { + // sets App start as finished when the very first activity calls onResume + firstActivityResumed = true; + AppStartState.getInstance().setAppStartEnd(); + } + if (application != null) { + application.unregisterActivityLifecycleCallbacks(this); + } + } @Override public void onActivityPaused(@NotNull Activity activity) {} 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 68acc87fd5..1f3005a5fe 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 @@ -6,6 +6,7 @@ import android.app.ActivityManager.RunningAppProcessInfo import android.app.Application import android.os.Bundle import io.sentry.Breadcrumb +import io.sentry.DateUtils import io.sentry.Hub import io.sentry.Scope import io.sentry.SentryDate @@ -650,66 +651,142 @@ class ActivityLifecycleIntegrationTest { } @Test - fun `App start end time is set`() { - val sut = fixture.getSut(14) + fun `When firstActivityCreated is true, start transaction with given appStartTime`() { + val sut = fixture.getSut() fixture.options.tracesSampleRate = 1.0 sut.register(fixture.hub, fixture.options) - setAppStartTime() + val date = SentryNanotimeDate(Date(0), 0) + setAppStartTime(date) val activity = mock() - sut.onActivityCreated(activity, null) - sut.onActivityResumed(activity) + sut.onActivityCreated(activity, fixture.bundle) - // SystemClock.uptimeMillis() always returns 0, can't assert real values - assertNotNull(AppStartState.getInstance().appStartInterval) + // call only once + verify(fixture.hub).startTransaction(any(), check { assertEquals(date, it.startTimestamp) }) } @Test - fun `App start end time isnt set if not foregroundImportance`() { - val sut = fixture.getSut(14, importance = RunningAppProcessInfo.IMPORTANCE_BACKGROUND) + fun `When firstActivityCreated is true, do not create app start span if not foregroundImportance`() { + val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_BACKGROUND) fixture.options.tracesSampleRate = 1.0 sut.register(fixture.hub, fixture.options) - setAppStartTime() + // usually set by SentryPerformanceProvider + val date = SentryNanotimeDate(Date(0), 0) + setAppStartTime(date) + AppStartState.getInstance().setAppStartEnd(1) val activity = mock() - sut.onActivityCreated(activity, null) - sut.onActivityResumed(activity) + sut.onActivityCreated(activity, fixture.bundle) - assertNull(AppStartState.getInstance().appStartInterval) + // call only once + verify(fixture.hub).startTransaction(any(), check { assertNull(it.startTimestamp) }) } @Test - fun `When firstActivityCreated is true, start transaction with given appStartTime`() { - val sut = fixture.getSut() + fun `Create and finish app start span immediately in case SDK init is deferred`() { + val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_FOREGROUND) fixture.options.tracesSampleRate = 1.0 sut.register(fixture.hub, fixture.options) - val date = SentryNanotimeDate(Date(0), 0) - setAppStartTime(date) + // usually set by SentryPerformanceProvider + val startDate = SentryNanotimeDate(Date(0), 0) + setAppStartTime(startDate) + AppStartState.getInstance().setColdStart(false) + AppStartState.getInstance().setAppStartEnd(1) + + val endDate = AppStartState.getInstance().appStartEndTime!! val activity = mock() sut.onActivityCreated(activity, fixture.bundle) - // call only once - verify(fixture.hub).startTransaction(any(), check { assertEquals(date, it.startTimestamp) }) + val appStartSpanCount = fixture.transaction.children.count { + it.spanContext.operation.startsWith("app.start.warm") && + it.startDate.nanoTimestamp() == startDate.nanoTimestamp() && + it.finishDate!!.nanoTimestamp() == endDate.nanoTimestamp() + } + assertEquals(1, appStartSpanCount) } @Test - fun `When firstActivityCreated is true, do not use appStartTime if not foregroundImportance`() { - val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_BACKGROUND) + fun `When SentryPerformanceProvider is disabled, app start time span is still created`() { + val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_FOREGROUND) fixture.options.tracesSampleRate = 1.0 sut.register(fixture.hub, fixture.options) - val date = SentryNanotimeDate(Date(0), 0) - setAppStartTime(date) + // usually done by SentryPerformanceProvider, if disabled it's done by + // SentryAndroid.init + val startDate = SentryNanotimeDate(Date(0), 0) + setAppStartTime(startDate) + AppStartState.getInstance().setColdStart(false) + // when activity is created val activity = mock() sut.onActivityCreated(activity, fixture.bundle) + // then app-start end time should still be null + assertNull(AppStartState.getInstance().appStartEndTime) - // call only once - verify(fixture.hub).startTransaction(any(), check { assertNull(it.startTimestamp) }) + // when activity is resumed + sut.onActivityResumed(activity) + // end-time should be set + assertNotNull(AppStartState.getInstance().appStartEndTime) + } + + @Test + fun `When app-start end time is already set, it should not be overwritten`() { + val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_FOREGROUND) + fixture.options.tracesSampleRate = 1.0 + sut.register(fixture.hub, fixture.options) + + // usually done by SentryPerformanceProvider + val startDate = SentryNanotimeDate(Date(0), 0) + setAppStartTime(startDate) + AppStartState.getInstance().setColdStart(false) + AppStartState.getInstance().setAppStartEnd(1234) + + // when activity is created and resumed + val activity = mock() + sut.onActivityCreated(activity, fixture.bundle) + sut.onActivityResumed(activity) + + // then the end time should not be overwritten + assertEquals( + DateUtils.millisToNanos(1234), + AppStartState.getInstance().appStartEndTime!!.nanoTimestamp() + ) + } + + @Test + fun `When activity lifecycle happens multiple times, app-start end time should not be overwritten`() { + val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_FOREGROUND) + fixture.options.tracesSampleRate = 1.0 + sut.register(fixture.hub, fixture.options) + + // usually done by SentryPerformanceProvider + val startDate = SentryNanotimeDate(Date(0), 0) + setAppStartTime(startDate) + AppStartState.getInstance().setColdStart(false) + + // when activity is created, started and resumed multiple times + val activity = mock() + sut.onActivityCreated(activity, fixture.bundle) + sut.onActivityStarted(activity) + sut.onActivityResumed(activity) + + val firstAppStartEndTime = AppStartState.getInstance().appStartEndTime + + Thread.sleep(1) + sut.onActivityPaused(activity) + sut.onActivityStopped(activity) + sut.onActivityStarted(activity) + sut.onActivityResumed(activity) + + // then the end time should not be overwritten + assertEquals( + firstAppStartEndTime!!.nanoTimestamp(), + AppStartState.getInstance().appStartEndTime!!.nanoTimestamp() + ) } @Test diff --git a/sentry-android-core/src/test/java/io/sentry/android/core/SentryPerformanceProviderTest.kt b/sentry-android-core/src/test/java/io/sentry/android/core/SentryPerformanceProviderTest.kt index 611c087dd1..cf3ca7c2ea 100644 --- a/sentry-android-core/src/test/java/io/sentry/android/core/SentryPerformanceProviderTest.kt +++ b/sentry-android-core/src/test/java/io/sentry/android/core/SentryPerformanceProviderTest.kt @@ -1,16 +1,20 @@ package io.sentry.android.core +import android.app.Application import android.content.pm.ProviderInfo import android.os.Bundle import androidx.test.ext.junit.runners.AndroidJUnit4 import io.sentry.SentryNanotimeDate import org.junit.runner.RunWith +import org.mockito.kotlin.any import org.mockito.kotlin.mock +import org.mockito.kotlin.verify import java.util.Date import kotlin.test.BeforeTest import kotlin.test.Test import kotlin.test.assertEquals import kotlin.test.assertFalse +import kotlin.test.assertNotNull import kotlin.test.assertTrue @RunWith(AndroidJUnit4::class) @@ -73,6 +77,26 @@ class SentryPerformanceProviderTest { assertFalse(AppStartState.getInstance().isColdStart!!) } + @Test + fun `provider sets app start end on first activity resume, and unregisters afterwards`() { + val providerInfo = ProviderInfo() + + val mockContext = ContextUtilsTest.createMockContext(true) + providerInfo.authority = AUTHORITY + + val provider = SentryPerformanceProvider() + provider.attachInfo(mockContext, providerInfo) + + provider.onActivityCreated(mock(), Bundle()) + provider.onActivityResumed(mock()) + + assertNotNull(AppStartState.getInstance().appStartInterval) + assertNotNull(AppStartState.getInstance().appStartEndTime) + + verify((mockContext.applicationContext as Application)) + .unregisterActivityLifecycleCallbacks(any()) + } + companion object { private const val AUTHORITY = "io.sentry.sample.SentryPerformanceProvider" }