Refactor background start detection in app start traces

firebase-perf/CHANGELOG.md

@@ -1,4 +1,5 @@
 # Unreleased
+- [fixed] Fixed the behavior of app start traces on API 34+ devices.
 
 # 22.0.1
 

firebase-perf/src/main/java/com/google/firebase/perf/metrics/AppStartTrace.java

@@ -75,6 +75,11 @@ public class AppStartTrace implements ActivityLifecycleCallbacks, LifecycleObser
   private static final @NonNull Timer PERF_CLASS_LOAD_TIME = new Clock().getTime();
   private static final long MAX_LATENCY_BEFORE_UI_INIT = TimeUnit.MINUTES.toMicros(1);
 
+  // If the `mainThreadRunnableTime` was set within this duration, the assumption
+  // is that it was called immediately before `onActivityCreated` in foreground starts on API 34+.
+  // See b/339891952.
+  private static final long MAX_BACKGROUND_RUNNABLE_DELAY = TimeUnit.MILLISECONDS.toMicros(50);
+
   // Core pool size 0 allows threads to shut down if they're idle
   private static final int CORE_POOL_SIZE = 0;
   private static final int MAX_POOL_SIZE = 1; // Only need single thread
@@ -111,6 +116,9 @@ public class AppStartTrace implements ActivityLifecycleCallbacks, LifecycleObser
   private final @Nullable Timer processStartTime;
   private final @Nullable Timer firebaseClassLoadTime;
   private Timer onCreateTime = null;
+
+  // TODO(b/339891952): Explore simplifying Timers in app start trace to use timestamps.
+  private Timer mainThreadRunnableTime = null;
   private Timer onStartTime = null;
   private Timer onResumeTime = null;
   private Timer firstForegroundTime = null;
@@ -319,8 +327,44 @@ private void recordOnDrawFrontOfQueue() {
     logExperimentTrace(this.experimentTtid);
   }
 
+  /**
+   * Sets the `isStartedFromBackground` flag to `true` if the `mainThreadRunnableTime` was set
+   * from the `StartFromBackgroundRunnable`.
+   * <p>
+   * If it's prior to API 34, it's always set to true if `mainThreadRunnableTime` was set.
+   * <p>
+   * If it's on or after API 34, and it was called less than `MAX_BACKGROUND_RUNNABLE_DELAY`
+   * before `onActivityCreated`, the
+   * assumption is that it was called immediately before the activity lifecycle callbacks in a
+   * foreground start.
+   * See b/339891952.
+   */
+  private void resolveIsStartedFromBackground() {
+    // If the mainThreadRunnableTime is null, either the runnable hasn't run, or this check has
+    // already been made.
+    if (mainThreadRunnableTime == null) {
+      return;
+    }
+
+    // If the `mainThreadRunnableTime` was set prior to API 34, it's always assumed that's it's
+    // a background start.
+    // Otherwise it's assumed to be a background start if the runnable was set more than
+    // `MAX_BACKGROUND_RUNNABLE_DELAY`
+    // before the first `onActivityCreated` call.
+    // TODO(b/339891952): Investigate removing the API check.
+    if ((Build.VERSION.SDK_INT < 34)
+        || (mainThreadRunnableTime.getDurationMicros() > MAX_BACKGROUND_RUNNABLE_DELAY)) {
+      isStartedFromBackground = true;
+    }
+
+    // Set this to null to prevent additional checks.
+    mainThreadRunnableTime = null;
+  }
+
   @Override
   public synchronized void onActivityCreated(Activity activity, Bundle savedInstanceState) {
+    resolveIsStartedFromBackground();
+
     if (isStartedFromBackground || onCreateTime != null // An activity already called onCreate()
     ) {
       return;
@@ -559,9 +603,9 @@ public static boolean isScreenOn(Context appContext) {
   /**
    * We use StartFromBackgroundRunnable to detect if app is started from background or foreground.
    * If app is started from background, we do not generate AppStart trace. This runnable is posted
-   * to main UI thread from FirebasePerfEarly. If app is started from background, this runnable will
-   * be executed before any activity's onCreate() method. If app is started from foreground,
-   * activity's onCreate() method is executed before this runnable.
+   * to main UI thread from FirebasePerfEarly. If `onActivityCreate` has never been called, we
+   * record the timestamp - which allows `onActivityCreate` to determine whether it was a background
+   * app start or not.
    */
   public static class StartFromBackgroundRunnable implements Runnable {
     private final AppStartTrace trace;
@@ -572,9 +616,9 @@ public StartFromBackgroundRunnable(final AppStartTrace trace) {
 
     @Override
     public void run() {
-      // if no activity has ever been created.
+      // Only set the `mainThreadRunnableTime` if `onActivityCreate` has never been called.
       if (trace.onCreateTime == null) {
-        trace.isStartedFromBackground = true;
+        trace.mainThreadRunnableTime = new Timer();
       }
     }
   }
@@ -614,7 +658,7 @@ Timer getOnResumeTime() {
   }
 
   @VisibleForTesting
-  void setIsStartFromBackground() {
-    isStartedFromBackground = true;
+  void setMainThreadRunnableTime(Timer timer) {
+    mainThreadRunnableTime = timer;
   }
 }

firebase-perf/src/test/java/com/google/firebase/perf/metrics/AppStartTraceTest.java

@@ -18,6 +18,7 @@
 import static org.mockito.ArgumentMatchers.isA;
 import static org.mockito.Mockito.doAnswer;
 import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.spy;
 import static org.mockito.Mockito.times;
 import static org.mockito.Mockito.verify;
 import static org.mockito.Mockito.when;
@@ -238,11 +239,44 @@ public void testDelayedAppStart() {
   }
 
   @Test
-  public void testStartFromBackground() {
+  public void testStartFromBackground_within50ms() {
     FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
+    Timer fakeTimer = spy(new Timer(currentTime));
     AppStartTrace trace =
         new AppStartTrace(transportManager, clock, configResolver, fakeExecutorService);
-    trace.setIsStartFromBackground();
+    trace.registerActivityLifecycleCallbacks(appContext);
+    trace.setMainThreadRunnableTime(fakeTimer);
+
+    // See AppStartTrace.MAX_BACKGROUND_RUNNABLE_DELAY.
+    when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.MILLISECONDS.toMicros(50) - 1);
+    trace.onActivityCreated(activity1, bundle);
+    Assert.assertNotNull(trace.getOnCreateTime());
+    ++currentTime;
+    trace.onActivityStarted(activity1);
+    Assert.assertNotNull(trace.getOnStartTime());
+    ++currentTime;
+    trace.onActivityResumed(activity1);
+    Assert.assertNotNull(trace.getOnResumeTime());
+    fakeExecutorService.runAll();
+    // There should be a trace sent since the delay between the main thread and onActivityCreated
+    // is limited.
+    verify(transportManager, times(1))
+        .log(
+            traceArgumentCaptor.capture(),
+            ArgumentMatchers.nullable(ApplicationProcessState.class));
+  }
+
+  @Test
+  public void testStartFromBackground_moreThan50ms() {
+    FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
+    Timer fakeTimer = spy(new Timer(currentTime));
+    AppStartTrace trace =
+        new AppStartTrace(transportManager, clock, configResolver, fakeExecutorService);
+    trace.registerActivityLifecycleCallbacks(appContext);
+    trace.setMainThreadRunnableTime(fakeTimer);
+
+    // See AppStartTrace.MAX_BACKGROUND_RUNNABLE_DELAY.
+    when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.MILLISECONDS.toMicros(50) + 1);
     trace.onActivityCreated(activity1, bundle);
     Assert.assertNull(trace.getOnCreateTime());
     ++currentTime;
@@ -252,6 +286,7 @@ public void testStartFromBackground() {
     trace.onActivityResumed(activity1);
     Assert.assertNull(trace.getOnResumeTime());
     // There should be no trace sent.
+    fakeExecutorService.runAll();
     verify(transportManager, times(0))
         .log(
             traceArgumentCaptor.capture(),