diff --git a/firebase-perf/CHANGELOG.md b/firebase-perf/CHANGELOG.md index fd06467ade2..5ff802164c1 100644 --- a/firebase-perf/CHANGELOG.md +++ b/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. diff --git a/firebase-perf/src/main/java/com/google/firebase/perf/metrics/AppStartTrace.java b/firebase-perf/src/main/java/com/google/firebase/perf/metrics/AppStartTrace.java index 813c8988383..652cbd71a55 100644 --- a/firebase-perf/src/main/java/com/google/firebase/perf/metrics/AppStartTrace.java +++ b/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. + * + *

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: + *

+ * 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 diff --git a/firebase-perf/src/test/java/com/google/firebase/perf/metrics/AppStartTraceTest.java b/firebase-perf/src/test/java/com/google/firebase/perf/metrics/AppStartTraceTest.java index daa80ad29a2..715b1a11d0f 100644 --- a/firebase-perf/src/test/java/com/google/firebase/perf/metrics/AppStartTraceTest.java +++ b/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() {