Skip to content

Commit b8f20ea

Browse files
committed
firebase-perf: widen background-start timing window to 1000ms (#8103)
The API-34 fix in 22.0.2 (PR #7281) used a 50 ms MAX_BACKGROUND_RUNNABLE_DELAY to tell cold foreground starts from genuine background starts. That threshold was calibrated against a near-empty test app on API 35, where the gap between StartFromBackgroundRunnable firing and the first onActivityCreated was ~10 ms. On API 34+ physical devices, the gap is dominated by Android's main-thread vs Binder scheduling, not by app work: - 316 ms on a minimal ContentProvider repro (issue #5920, PhilGlass). - 204 ms on a large production app (issue #8103, manavchandrakar29011994). 50 ms is well below both, so _app_start is unconditionally suppressed for typical real-world apps on the very devices the fix was meant to support. Bump MAX_BACKGROUND_RUNNABLE_DELAY to 1000 ms. The mechanism (timing window) and the warm-start guard introduced in PR #7281 (mainThreadRunnableTime is only set when onCreateTime == null) are unchanged. Genuine warm starts where the process was forked for background work seconds-to-minutes before any activity launch are still suppressed, since their gap far exceeds 1000 ms and MAX_LATENCY_BEFORE_UI_INIT (60 s) remains the upper backstop. Tests: - Rename the existing 50 ms tests to _within1000ms / _moreThan1000ms. - Add testStartFromBackground_largeAppGap_isForegroundStart: ~300 ms gap on API 34 now logs the trace (regression-locks #8103). - Add testStartFromBackground_warmStart_stillSuppressed: 10 s gap is still suppressed.
1 parent f5b1aba commit b8f20ea

3 files changed

Lines changed: 78 additions & 6 deletions

File tree

firebase-perf/CHANGELOG.md

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,9 @@
11
# Unreleased
22

3+
- [fixed] Fixed `_app_start` traces being suppressed on API 34+ devices for typical
4+
real-world apps by widening the foreground/background-start timing window to account
5+
for Android's main-thread vs Binder scheduling on physical devices. [#8103]
6+
37
# 22.0.5
48

59
- [changed] Bumped internal dependencies.

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

Lines changed: 13 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -76,8 +76,19 @@ public class AppStartTrace implements ActivityLifecycleCallbacks, LifecycleObser
7676

7777
// If the `mainThreadRunnableTime` was set within this duration, the assumption
7878
// is that it was called immediately before `onActivityCreated` in foreground starts on API 34+.
79-
// See b/339891952.
80-
private static final long MAX_BACKGROUND_RUNNABLE_DELAY = TimeUnit.MILLISECONDS.toMicros(50);
79+
//
80+
// On API 34+, Android may drain posted main-thread runnables before processing the
81+
// Activity-launch Binder transaction even during a genuine cold foreground start. The
82+
// resulting gap between `StartFromBackgroundRunnable` firing and the first
83+
// `onActivityCreated` is dominated by system scheduling, not by app work, and has been
84+
// measured at ~316ms on a minimal repro app and ~204ms on a large production app on
85+
// physical Pixel devices. The threshold must therefore comfortably exceed these
86+
// real-world gaps; 1000ms provides ~5x headroom over the worst measured cold-start gap
87+
// while still being two orders of magnitude below `MAX_LATENCY_BEFORE_UI_INIT` so that
88+
// genuine warm starts (where the process was forked for background work seconds-to-
89+
// minutes before any activity launch) remain correctly suppressed.
90+
// See b/339891952 and https://github.com/firebase/firebase-android-sdk/issues/8103.
91+
private static final long MAX_BACKGROUND_RUNNABLE_DELAY = TimeUnit.MILLISECONDS.toMicros(1000);
8192

8293
// Core pool size 0 allows threads to shut down if they're idle
8394
private static final int CORE_POOL_SIZE = 0;

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

Lines changed: 61 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -239,7 +239,7 @@ public void testDelayedAppStart() {
239239
}
240240

241241
@Test
242-
public void testStartFromBackground_within50ms() {
242+
public void testStartFromBackground_within1000ms() {
243243
FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
244244
Timer fakeTimer = spy(new Timer(currentTime));
245245
AppStartTrace trace =
@@ -248,7 +248,7 @@ public void testStartFromBackground_within50ms() {
248248
trace.setMainThreadRunnableTime(fakeTimer);
249249

250250
// See AppStartTrace.MAX_BACKGROUND_RUNNABLE_DELAY.
251-
when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.MILLISECONDS.toMicros(50) - 1);
251+
when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.MILLISECONDS.toMicros(1000) - 1);
252252
trace.onActivityCreated(activity1, bundle);
253253
Assert.assertNotNull(trace.getOnCreateTime());
254254
++currentTime;
@@ -267,7 +267,7 @@ public void testStartFromBackground_within50ms() {
267267
}
268268

269269
@Test
270-
public void testStartFromBackground_moreThan50ms() {
270+
public void testStartFromBackground_moreThan1000ms() {
271271
FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
272272
Timer fakeTimer = spy(new Timer(currentTime));
273273
AppStartTrace trace =
@@ -276,7 +276,7 @@ public void testStartFromBackground_moreThan50ms() {
276276
trace.setMainThreadRunnableTime(fakeTimer);
277277

278278
// See AppStartTrace.MAX_BACKGROUND_RUNNABLE_DELAY.
279-
when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.MILLISECONDS.toMicros(50) + 1);
279+
when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.MILLISECONDS.toMicros(1000) + 1);
280280
trace.onActivityCreated(activity1, bundle);
281281
Assert.assertNull(trace.getOnCreateTime());
282282
++currentTime;
@@ -293,6 +293,63 @@ public void testStartFromBackground_moreThan50ms() {
293293
ArgumentMatchers.nullable(ApplicationProcessState.class));
294294
}
295295

296+
// Regression test for https://github.com/firebase/firebase-android-sdk/issues/8103.
297+
// On API 34+ physical devices, the gap between StartFromBackgroundRunnable firing and the
298+
// first onActivityCreated has been measured at ~204-316ms on real apps; the previous 50ms
299+
// threshold misclassified these as background starts and suppressed _app_start traces.
300+
@Test
301+
public void testStartFromBackground_largeAppGap_isForegroundStart() {
302+
FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
303+
Timer fakeTimer = spy(new Timer(currentTime));
304+
AppStartTrace trace =
305+
new AppStartTrace(transportManager, clock, configResolver, fakeExecutorService);
306+
trace.registerActivityLifecycleCallbacks(appContext);
307+
trace.setMainThreadRunnableTime(fakeTimer);
308+
309+
// Simulates the API 34+ scheduling gap observed in real-world apps.
310+
when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.MILLISECONDS.toMicros(300));
311+
trace.onActivityCreated(activity1, bundle);
312+
Assert.assertNotNull(trace.getOnCreateTime());
313+
++currentTime;
314+
trace.onActivityStarted(activity1);
315+
Assert.assertNotNull(trace.getOnStartTime());
316+
++currentTime;
317+
trace.onActivityResumed(activity1);
318+
Assert.assertNotNull(trace.getOnResumeTime());
319+
fakeExecutorService.runAll();
320+
verify(transportManager, times(1))
321+
.log(
322+
traceArgumentCaptor.capture(),
323+
ArgumentMatchers.nullable(ApplicationProcessState.class));
324+
}
325+
326+
// Genuine warm starts (process alive for background work, activity launched seconds later)
327+
// must still be classified as background and suppressed.
328+
@Test
329+
public void testStartFromBackground_warmStart_stillSuppressed() {
330+
FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
331+
Timer fakeTimer = spy(new Timer(currentTime));
332+
AppStartTrace trace =
333+
new AppStartTrace(transportManager, clock, configResolver, fakeExecutorService);
334+
trace.registerActivityLifecycleCallbacks(appContext);
335+
trace.setMainThreadRunnableTime(fakeTimer);
336+
337+
when(fakeTimer.getDurationMicros()).thenReturn(TimeUnit.SECONDS.toMicros(10));
338+
trace.onActivityCreated(activity1, bundle);
339+
Assert.assertNull(trace.getOnCreateTime());
340+
++currentTime;
341+
trace.onActivityStarted(activity1);
342+
Assert.assertNull(trace.getOnStartTime());
343+
++currentTime;
344+
trace.onActivityResumed(activity1);
345+
Assert.assertNull(trace.getOnResumeTime());
346+
fakeExecutorService.runAll();
347+
verify(transportManager, times(0))
348+
.log(
349+
traceArgumentCaptor.capture(),
350+
ArgumentMatchers.nullable(ApplicationProcessState.class));
351+
}
352+
296353
@Test
297354
@Config(sdk = 26)
298355
public void timeToInitialDisplay_isLogged() {

0 commit comments

Comments
 (0)