Hotfix/jrc 8103.bump.app.start.runnable.delay

firebase-perf/CHANGELOG.md

@@ -1,5 +1,9 @@
 # Unreleased
 
+- [fixed] Fixed `_app_start` traces being suppressed on API 34+ devices for typical
+  real-world apps by widening the foreground/background-start timing window to account
+  for Android's main-thread vs Binder scheduling on physical devices. [#8103]
+
 # 22.0.5
 
 - [changed] Bumped internal dependencies.

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

@@ -76,8 +76,19 @@ public class AppStartTrace implements ActivityLifecycleCallbacks, LifecycleObser
 
   // 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);
+  //
+  // On API 34+, Android may drain posted main-thread runnables before processing the
+  // Activity-launch Binder transaction even during a genuine cold foreground start. The
+  // resulting gap between `StartFromBackgroundRunnable` firing and the first
+  // `onActivityCreated` is dominated by system scheduling, not by app work, and has been
+  // measured at ~316ms on a minimal repro app and ~204ms on a large production app on
+  // physical Pixel devices. The threshold must therefore comfortably exceed these
+  // real-world gaps; 1000ms provides ~5x headroom over the worst measured cold-start gap
+  // while still being two orders of magnitude below `MAX_LATENCY_BEFORE_UI_INIT` so that
+  // genuine warm starts (where the process was forked for background work seconds-to-
+  // minutes before any activity launch) remain correctly suppressed.
+  // See b/339891952 and https://github.com/firebase/firebase-android-sdk/issues/8103.
+  private static final long MAX_BACKGROUND_RUNNABLE_DELAY = TimeUnit.MILLISECONDS.toMicros(1000);
 
   // Core pool size 0 allows threads to shut down if they're idle
   private static final int CORE_POOL_SIZE = 0;
@@ -336,7 +347,25 @@ private void recordOnDrawFrontOfQueue() {
    * before `onActivityCreated`, the
    * assumption is that it was called immediately before the activity lifecycle callbacks in a
    * foreground start.
-   * See b/339891952.
+   * See b/339891952 and https://github.com/firebase/firebase-android-sdk/issues/8103.
+   *
+   * <p>TODO(b/339891952): Replace this timing-window heuristic with a causal signal.
+   * The current approach infers "was the process forked to launch an Activity?" from the
+   * ordering of a posted runnable vs the first onActivityCreated callback, which is
+   * inherently fragile (its calibration depends on Android scheduling behavior that has
+   * already shifted once on API 34+ and could shift again). Better candidates:
+   * <ul>
+   *   <li>API 35+: use {@code ActivityManager.getHistoricalProcessStartReasons} /
+   *       {@code ApplicationStartInfo}, which authoritatively reports the start reason
+   *       ({@code START_REASON_LAUNCHER}, {@code START_REASON_SERVICE},
+   *       {@code START_REASON_CONTENT_PROVIDER}, etc.). This removes the heuristic
+   *       entirely on supported devices.
+   *   <li>API 34: capture {@code ActivityManager.RunningAppProcessInfo.importanceReasonCode}
+   *       and {@code .importance} once early in {@code FirebasePerfEarly} (before any of
+   *       our own ContentProvider work mutates the cause), and combine with the timing
+   *       window as a fallback for ambiguous cases.
+   * </ul>
+   * Adopting either of these would also let the API-34-vs-pre-34 branch below collapse.
    */
   private void resolveIsStartedFromBackground() {
     // If the mainThreadRunnableTime is null, either the runnable hasn't run, or this check has

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

@@ -239,7 +239,7 @@ public void testDelayedAppStart() {
   }
 
   @Test
-  public void testStartFromBackground_within50ms() {
+  public void testStartFromBackground_within1000ms() {
     FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
     Timer fakeTimer = spy(new Timer(currentTime));
     AppStartTrace trace =
@@ -248,7 +248,7 @@ public void testStartFromBackground_within50ms() {
     trace.setMainThreadRunnableTime(fakeTimer);
 
     // See AppStartTrace.MAX_BACKGROUND_RUNNABLE_DELAY.
-    when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.MILLISECONDS.toMicros(50) - 1);
+    when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.MILLISECONDS.toMicros(1000) - 1);
     trace.onActivityCreated(activity1, bundle);
     Assert.assertNotNull(trace.getOnCreateTime());
     ++currentTime;
@@ -267,7 +267,7 @@ public void testStartFromBackground_within50ms() {
   }
 
   @Test
-  public void testStartFromBackground_moreThan50ms() {
+  public void testStartFromBackground_moreThan1000ms() {
     FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
     Timer fakeTimer = spy(new Timer(currentTime));
     AppStartTrace trace =
@@ -276,7 +276,7 @@ public void testStartFromBackground_moreThan50ms() {
     trace.setMainThreadRunnableTime(fakeTimer);
 
     // See AppStartTrace.MAX_BACKGROUND_RUNNABLE_DELAY.
-    when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.MILLISECONDS.toMicros(50) + 1);
+    when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.MILLISECONDS.toMicros(1000) + 1);
     trace.onActivityCreated(activity1, bundle);
     Assert.assertNull(trace.getOnCreateTime());
     ++currentTime;
@@ -293,6 +293,63 @@ public void testStartFromBackground_moreThan50ms() {
             ArgumentMatchers.nullable(ApplicationProcessState.class));
   }
 
+  // Regression test for https://github.com/firebase/firebase-android-sdk/issues/8103.
+  // On API 34+ physical devices, the gap between StartFromBackgroundRunnable firing and the
+  // first onActivityCreated has been measured at ~204-316ms on real apps; the previous 50ms
+  // threshold misclassified these as background starts and suppressed _app_start traces.
+  @Test
+  public void testStartFromBackground_largeAppGap_isForegroundStart() {
+    FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
+    Timer fakeTimer = spy(new Timer(currentTime));
+    AppStartTrace trace =
+        new AppStartTrace(transportManager, clock, configResolver, fakeExecutorService);
+    trace.registerActivityLifecycleCallbacks(appContext);
+    trace.setMainThreadRunnableTime(fakeTimer);
+
+    // Simulates the API 34+ scheduling gap observed in real-world apps.
+    when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.MILLISECONDS.toMicros(300));
+    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();
+    verify(transportManager, times(1))
+        .log(
+            traceArgumentCaptor.capture(),
+            ArgumentMatchers.nullable(ApplicationProcessState.class));
+  }
+
+  // Genuine warm starts (process alive for background work, activity launched seconds later)
+  // must still be classified as background and suppressed.
+  @Test
+  public void testStartFromBackground_warmStart_stillSuppressed() {
+    FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
+    Timer fakeTimer = spy(new Timer(currentTime));
+    AppStartTrace trace =
+        new AppStartTrace(transportManager, clock, configResolver, fakeExecutorService);
+    trace.registerActivityLifecycleCallbacks(appContext);
+    trace.setMainThreadRunnableTime(fakeTimer);
+
+    when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.SECONDS.toMicros(10));
+    trace.onActivityCreated(activity1, bundle);
+    Assert.assertNull(trace.getOnCreateTime());
+    ++currentTime;
+    trace.onActivityStarted(activity1);
+    Assert.assertNull(trace.getOnStartTime());
+    ++currentTime;
+    trace.onActivityResumed(activity1);
+    Assert.assertNull(trace.getOnResumeTime());
+    fakeExecutorService.runAll();
+    verify(transportManager, times(0))
+        .log(
+            traceArgumentCaptor.capture(),
+            ArgumentMatchers.nullable(ApplicationProcessState.class));
+  }
+
   @Test
   @Config(sdk = 26)
   public void timeToInitialDisplay_isLogged() {