Check app start spans time and foreground state (#3550)

* App start now takes AppStartMetrics.appLaunchedInForeground variable to add spans to the transaction
* App starts longer than 1 minute are dropped (same as Firebase)
* added Activity lifecycle registration to check start launch time and foreground status
* added AppStartMetrics.registerApplicationForegroundCheck in the SentryPerformanceProvider and SentryAndroid.init, other than AppStartMetrics.onApplicationCreate
* ActivityLifecycleIntegration now reads first activity creation on create instead of class instantiation
* AppStartMetrics stops app start profiler if no activity is being created

CHANGELOG.md

@@ -1,5 +1,12 @@
 # Changelog
 
+## Unreleased
+
+### Fixes
+
+- Check app start spans time and ignore background app starts ([#3550](https://github.com/getsentry/sentry-java/pull/3550))
+  - This should eliminate long-lasting App Start transactions
+
 ## 7.12.0
 
 ### Features

sentry-android-core/api/sentry-android-core.api

@@ -427,7 +427,7 @@ public class io/sentry/android/core/performance/ActivityLifecycleTimeSpan : java
 	public final fun getOnStart ()Lio/sentry/android/core/performance/TimeSpan;
 }
 
-public class io/sentry/android/core/performance/AppStartMetrics {
+public class io/sentry/android/core/performance/AppStartMetrics : io/sentry/android/core/performance/ActivityLifecycleCallbacksAdapter {
 	public fun <init> ()V
 	public fun addActivityLifecycleTimeSpans (Lio/sentry/android/core/performance/ActivityLifecycleTimeSpan;)V
 	public fun clear ()V
@@ -443,10 +443,13 @@ public class io/sentry/android/core/performance/AppStartMetrics {
 	public static fun getInstance ()Lio/sentry/android/core/performance/AppStartMetrics;
 	public fun getSdkInitTimeSpan ()Lio/sentry/android/core/performance/TimeSpan;
 	public fun isAppLaunchedInForeground ()Z
+	public fun onActivityCreated (Landroid/app/Activity;Landroid/os/Bundle;)V
 	public static fun onApplicationCreate (Landroid/app/Application;)V
 	public static fun onApplicationPostCreate (Landroid/app/Application;)V
 	public static fun onContentProviderCreate (Landroid/content/ContentProvider;)V
 	public static fun onContentProviderPostCreate (Landroid/content/ContentProvider;)V
+	public fun registerApplicationForegroundCheck (Landroid/app/Application;)V
+	public fun setAppLaunchedInForeground (Z)V
 	public fun setAppStartProfiler (Lio/sentry/ITransactionProfiler;)V
 	public fun setAppStartSamplingDecision (Lio/sentry/TracesSamplingDecision;)V
 	public fun setAppStartType (Lio/sentry/android/core/performance/AppStartMetrics$AppStartType;)V

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

@@ -21,6 +21,7 @@
 import io.sentry.NoOpTransaction;
 import io.sentry.SentryDate;
 import io.sentry.SentryLevel;
+import io.sentry.SentryNanotimeDate;
 import io.sentry.SentryOptions;
 import io.sentry.SpanStatus;
 import io.sentry.TracesSamplingDecision;
@@ -37,6 +38,7 @@
 import java.io.Closeable;
 import java.io.IOException;
 import java.lang.ref.WeakReference;
+import java.util.Date;
 import java.util.Map;
 import java.util.WeakHashMap;
 import java.util.concurrent.Future;
@@ -75,7 +77,7 @@ public final class ActivityLifecycleIntegration
   private @Nullable ISpan appStartSpan;
   private final @NotNull WeakHashMap<Activity, ISpan> ttidSpanMap = new WeakHashMap<>();
   private final @NotNull WeakHashMap<Activity, ISpan> ttfdSpanMap = new WeakHashMap<>();
-  private @NotNull SentryDate lastPausedTime = AndroidDateUtils.getCurrentSentryDateTime();
+  private @NotNull SentryDate lastPausedTime = new SentryNanotimeDate(new Date(0), 0);
   private final @NotNull Handler mainHandler = new Handler(Looper.getMainLooper());
   private @Nullable Future<?> ttfdAutoCloseFuture = null;
 
@@ -627,6 +629,14 @@ WeakHashMap<Activity, ISpan> getTtfdSpanMap() {
   }
 
   private void setColdStart(final @Nullable Bundle savedInstanceState) {
+    // The very first activity start timestamp cannot be set to the class instantiation time, as it
+    // may happen before an activity is started (service, broadcast receiver, etc). So we set it
+    // here.
+    if (hub != null && lastPausedTime.nanoTimestamp() == 0) {
+      lastPausedTime = hub.getOptions().getDateProvider().now();
+    } else if (lastPausedTime.nanoTimestamp() == 0) {
+      lastPausedTime = AndroidDateUtils.getCurrentSentryDateTime();
+    }
     if (!firstActivityCreated) {
       // if Activity has savedInstanceState then its a warm start
       // https://developer.android.com/topic/performance/vitals/launch-time#warm

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

@@ -1,6 +1,7 @@
 package io.sentry.android.core;
 
 import android.annotation.SuppressLint;
+import android.app.Application;
 import android.content.Context;
 import android.os.Process;
 import android.os.SystemClock;
@@ -141,6 +142,10 @@ public static synchronized void init(
                 appStartTimeSpan.setStartedAt(Process.getStartUptimeMillis());
               }
             }
+            if (context.getApplicationContext() instanceof Application) {
+              appStartMetrics.registerApplicationForegroundCheck(
+                  (Application) context.getApplicationContext());
+            }
             final @NotNull TimeSpan sdkInitTimeSpan = appStartMetrics.getSdkInitTimeSpan();
             if (sdkInitTimeSpan.hasNotStarted()) {
               sdkInitTimeSpan.setStartedAt(sdkInitMillis);

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

@@ -201,6 +201,7 @@ private void onAppLaunched(
 
     final @NotNull TimeSpan appStartTimespan = appStartMetrics.getAppStartTimeSpan();
     appStartTimespan.setStartedAt(Process.getStartUptimeMillis());
+    appStartMetrics.registerApplicationForegroundCheck(app);
 
     final AtomicBoolean firstDrawDone = new AtomicBoolean(false);
 

sentry-android-core/src/main/java/io/sentry/android/core/performance/AppStartMetrics.java

@@ -1,10 +1,18 @@
 package io.sentry.android.core.performance;
 
+import android.app.Activity;
 import android.app.Application;
 import android.content.ContentProvider;
+import android.os.Bundle;
+import android.os.Handler;
+import android.os.Looper;
 import android.os.SystemClock;
+import androidx.annotation.NonNull;
 import androidx.annotation.Nullable;
+import androidx.annotation.VisibleForTesting;
 import io.sentry.ITransactionProfiler;
+import io.sentry.SentryDate;
+import io.sentry.SentryNanotimeDate;
 import io.sentry.TracesSamplingDecision;
 import io.sentry.android.core.ContextUtils;
 import io.sentry.android.core.SentryAndroidOptions;
@@ -13,6 +21,7 @@
 import java.util.HashMap;
 import java.util.List;
 import java.util.Map;
+import java.util.concurrent.TimeUnit;
 import org.jetbrains.annotations.ApiStatus;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.TestOnly;
@@ -23,7 +32,7 @@
  * transformed into SDK specific txn/span data structures.
  */
 @ApiStatus.Internal
-public class AppStartMetrics {
+public class AppStartMetrics extends ActivityLifecycleCallbacksAdapter {
 
   public enum AppStartType {
     UNKNOWN,
@@ -45,6 +54,9 @@ public enum AppStartType {
   private final @NotNull List<ActivityLifecycleTimeSpan> activityLifecycles;
   private @Nullable ITransactionProfiler appStartProfiler = null;
   private @Nullable TracesSamplingDecision appStartSamplingDecision = null;
+  private @Nullable SentryDate onCreateTime = null;
+  private boolean appLaunchTooLong = false;
+  private boolean isCallbackRegistered = false;
 
   public static @NotNull AppStartMetrics getInstance() {
 
@@ -65,6 +77,7 @@ public AppStartMetrics() {
     applicationOnCreate = new TimeSpan();
     contentProviderOnCreates = new HashMap<>();
     activityLifecycles = new ArrayList<>();
+    appLaunchedInForeground = ContextUtils.isForegroundImportance();
   }
 
   /**
@@ -102,6 +115,11 @@ public boolean isAppLaunchedInForeground() {
     return appLaunchedInForeground;
   }
 
+  @VisibleForTesting
+  public void setAppLaunchedInForeground(final boolean appLaunchedInForeground) {
+    this.appLaunchedInForeground = appLaunchedInForeground;
+  }
+
   /**
    * Provides all collected content provider onCreate time spans
    *
@@ -137,12 +155,20 @@ public long getClassLoadedUptimeMs() {
       // Only started when sdk version is >= N
       final @NotNull TimeSpan appStartSpan = getAppStartTimeSpan();
       if (appStartSpan.hasStarted()) {
-        return appStartSpan;
+        return validateAppStartSpan(appStartSpan);
       }
     }
 
     // fallback: use sdk init time span, as it will always have a start time set
-    return getSdkInitTimeSpan();
+    return validateAppStartSpan(getSdkInitTimeSpan());
+  }
+
+  private @NotNull TimeSpan validateAppStartSpan(final @NotNull TimeSpan appStartSpan) {
+    // If the app launch took too long or it was launched in the background we return an empty span
+    if (appLaunchTooLong || !appLaunchedInForeground) {
+      return new TimeSpan();
+    }
+    return appStartSpan;
   }
 
   @TestOnly
@@ -158,6 +184,10 @@ public void clear() {
     }
     appStartProfiler = null;
     appStartSamplingDecision = null;
+    appLaunchTooLong = false;
+    appLaunchedInForeground = false;
+    onCreateTime = null;
+    isCallbackRegistered = false;
   }
 
   public @Nullable ITransactionProfiler getAppStartProfiler() {
@@ -195,7 +225,55 @@ public static void onApplicationCreate(final @NotNull Application application) {
     final @NotNull AppStartMetrics instance = getInstance();
     if (instance.applicationOnCreate.hasNotStarted()) {
       instance.applicationOnCreate.setStartedAt(now);
-      instance.appLaunchedInForeground = ContextUtils.isForegroundImportance();
+      instance.registerApplicationForegroundCheck(application);
+    }
+  }
+
+  /**
+   * Register a callback to check if an activity was started after the application was created
+   *
+   * @param application The application object to register the callback to
+   */
+  public void registerApplicationForegroundCheck(final @NotNull Application application) {
+    if (isCallbackRegistered) {
+      return;
+    }
+    isCallbackRegistered = true;
+    appLaunchedInForeground = appLaunchedInForeground || ContextUtils.isForegroundImportance();
+    application.registerActivityLifecycleCallbacks(instance);
+    new Handler(Looper.getMainLooper())
+        .post(
+            () -> {
+              // if no activity has ever been created, app was launched in background
+              if (onCreateTime == null) {
+                appLaunchedInForeground = false;
+              }
+              application.unregisterActivityLifecycleCallbacks(instance);
+              // we stop the app start profiler, as it's useless and likely to timeout
+              if (appStartProfiler != null && appStartProfiler.isRunning()) {
+                appStartProfiler.close();
+                appStartProfiler = null;
+              }
+            });
+  }
+
+  @Override
+  public void onActivityCreated(@NonNull Activity activity, @Nullable Bundle savedInstanceState) {
+    // An activity already called onCreate()
+    if (!appLaunchedInForeground || onCreateTime != null) {
+      return;
+    }
+    onCreateTime = new SentryNanotimeDate();
+
+    final long spanStartMillis = appStartSpan.getStartTimestampMs();
+    final long spanEndMillis =
+        appStartSpan.hasStopped()
+            ? appStartSpan.getProjectedStopTimestampMs()
+            : System.currentTimeMillis();
+    final long durationMillis = spanEndMillis - spanStartMillis;
+    // If the app was launched more than 1 minute ago, it's likely wrong
+    if (durationMillis > TimeUnit.MINUTES.toMillis(1)) {
+      appLaunchTooLong = true;
     }
   }
 

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
@@ -94,6 +95,7 @@ class ActivityLifecycleIntegrationTest {
 
             whenever(hub.options).thenReturn(options)
 
+            AppStartMetrics.getInstance().isAppLaunchedInForeground = true
             // We let the ActivityLifecycleIntegration create the proper transaction here
             val optionCaptor = argumentCaptor<TransactionOptions>()
             val contextCaptor = argumentCaptor<TransactionContext>()
@@ -709,15 +711,19 @@ class ActivityLifecycleIntegrationTest {
         sut.register(fixture.hub, fixture.options)
 
         val date = SentryNanotimeDate(Date(1), 0)
+        val date2 = SentryNanotimeDate(Date(2), 2)
         setAppStartTime(date)
 
         val activity = mock<Activity>()
+        // The activity onCreate date will be ignored
+        fixture.options.dateProvider = SentryDateProvider { date2 }
         sut.onActivityCreated(activity, fixture.bundle)
 
         verify(fixture.hub).startTransaction(
             any(),
             check<TransactionOptions> {
                 assertEquals(date.nanoTimestamp(), it.startTimestamp!!.nanoTimestamp())
+                assertNotEquals(date2.nanoTimestamp(), it.startTimestamp!!.nanoTimestamp())
                 assertFalse(it.isAppStartTransaction)
             }
         )
@@ -756,6 +762,30 @@ class ActivityLifecycleIntegrationTest {
         )
     }
 
+    @Test
+    fun `When firstActivityCreated is true and no app start time is set, default to onActivityCreated time`() {
+        val sut = fixture.getSut()
+        fixture.options.tracesSampleRate = 1.0
+        sut.register(fixture.hub, fixture.options)
+
+        // usually set by SentryPerformanceProvider
+        val date = SentryNanotimeDate(Date(1), 0)
+        val date2 = SentryNanotimeDate(Date(2), 2)
+
+        val activity = mock<Activity>()
+        // Activity onCreate date will be used
+        fixture.options.dateProvider = SentryDateProvider { date2 }
+        sut.onActivityCreated(activity, fixture.bundle)
+
+        verify(fixture.hub).startTransaction(
+            any(),
+            check<TransactionOptions> {
+                assertEquals(date2.nanoTimestamp(), it.startTimestamp!!.nanoTimestamp())
+                assertNotEquals(date.nanoTimestamp(), it.startTimestamp!!.nanoTimestamp())
+            }
+        )
+    }
+
     @Test
     fun `Create and finish app start span immediately in case SDK init is deferred`() {
         val sut = fixture.getSut(importance = RunningAppProcessInfo.IMPORTANCE_FOREGROUND)
@@ -940,6 +970,46 @@ class ActivityLifecycleIntegrationTest {
         assertEquals(span.startDate.nanoTimestamp(), date.nanoTimestamp())
     }
 
+    @Test
+    fun `When firstActivityCreated is true and app started more than 1 minute ago, app start spans are dropped`() {
+        val sut = fixture.getSut()
+        fixture.options.tracesSampleRate = 1.0
+        sut.register(fixture.hub, fixture.options)
+
+        val date = SentryNanotimeDate(Date(1), 0)
+        val duration = TimeUnit.MINUTES.toMillis(1) + 2
+        val durationNanos = TimeUnit.MILLISECONDS.toNanos(duration)
+        val stopDate = SentryNanotimeDate(Date(duration), durationNanos)
+        setAppStartTime(date, stopDate)
+
+        val activity = mock<Activity>()
+        sut.onActivityCreated(activity, null)
+
+        val appStartSpan = fixture.transaction.children.firstOrNull {
+            it.description == "Cold Start"
+        }
+        assertNull(appStartSpan)
+    }
+
+    @Test
+    fun `When firstActivityCreated is true and app started in background, app start spans are dropped`() {
+        val sut = fixture.getSut()
+        AppStartMetrics.getInstance().isAppLaunchedInForeground = false
+        fixture.options.tracesSampleRate = 1.0
+        sut.register(fixture.hub, fixture.options)
+
+        val date = SentryNanotimeDate(Date(1), 0)
+        setAppStartTime(date)
+
+        val activity = mock<Activity>()
+        sut.onActivityCreated(activity, null)
+
+        val appStartSpan = fixture.transaction.children.firstOrNull {
+            it.description == "Cold Start"
+        }
+        assertNull(appStartSpan)
+    }
+
     @Test
     fun `When firstActivityCreated is false, start transaction but not with given appStartTime`() {
         val sut = fixture.getSut()
@@ -1412,18 +1482,22 @@ class ActivityLifecycleIntegrationTest {
         shadowOf(Looper.getMainLooper()).idle()
     }
 
-    private fun setAppStartTime(date: SentryDate = SentryNanotimeDate(Date(1), 0)) {
+    private fun setAppStartTime(date: SentryDate = SentryNanotimeDate(Date(1), 0), stopDate: SentryDate? = null) {
         // set by SentryPerformanceProvider so forcing it here
         val sdkAppStartTimeSpan = AppStartMetrics.getInstance().sdkInitTimeSpan
         val appStartTimeSpan = AppStartMetrics.getInstance().appStartTimeSpan
         val millis = DateUtils.nanosToMillis(date.nanoTimestamp().toDouble()).toLong()
+        val stopMillis = DateUtils.nanosToMillis(stopDate?.nanoTimestamp()?.toDouble() ?: 0.0).toLong()
 
         sdkAppStartTimeSpan.setStartedAt(millis)
         sdkAppStartTimeSpan.setStartUnixTimeMs(millis)
-        sdkAppStartTimeSpan.setStoppedAt(0)
+        sdkAppStartTimeSpan.setStoppedAt(stopMillis)
 
         appStartTimeSpan.setStartedAt(millis)
         appStartTimeSpan.setStartUnixTimeMs(millis)
-        appStartTimeSpan.setStoppedAt(0)
+        appStartTimeSpan.setStoppedAt(stopMillis)
+        if (stopDate != null) {
+            AppStartMetrics.getInstance().onActivityCreated(mock(), mock())
+        }
     }
 }