Move app start trace build logic into a non-main thread. (#3008)

* Move app start trace build logic into a non-main thread.

* Fix style

* Incorporate comments

* Incorporate comments

Author: jeremyjiang-dev

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

@@ -25,6 +25,7 @@
 import com.google.android.gms.common.util.VisibleForTesting;
 import com.google.firebase.perf.logging.AndroidLogger;
 import com.google.firebase.perf.provider.FirebasePerfProvider;
+import com.google.firebase.perf.session.PerfSession;
 import com.google.firebase.perf.session.SessionManager;
 import com.google.firebase.perf.transport.TransportManager;
 import com.google.firebase.perf.util.Clock;
@@ -35,6 +36,9 @@
 import java.lang.ref.WeakReference;
 import java.util.ArrayList;
 import java.util.List;
+import java.util.concurrent.ExecutorService;
+import java.util.concurrent.LinkedBlockingQueue;
+import java.util.concurrent.ThreadPoolExecutor;
 import java.util.concurrent.TimeUnit;
 
 /**
@@ -55,7 +59,39 @@ public class AppStartTrace implements ActivityLifecycleCallbacks {
 
   private static final long MAX_LATENCY_BEFORE_UI_INIT = TimeUnit.MINUTES.toMicros(1);
 
+  // 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
+
   private static volatile AppStartTrace instance;
+  private static ExecutorService executorService;
+
+  private boolean isRegisteredForLifecycleCallbacks = false;
+  private final TransportManager transportManager;
+  private final Clock clock;
+  private Context appContext;
+  /**
+   * The first time onCreate() of any activity is called, the activity is saved as launchActivity.
+   */
+  private WeakReference<Activity> launchActivity;
+  /**
+   * The first time onResume() of any activity is called, the activity is saved as appStartActivity
+   */
+  private WeakReference<Activity> appStartActivity;
+
+  /**
+   * If the time difference between app starts and creation of any Activity is larger than
+   * MAX_LATENCY_BEFORE_UI_INIT, set mTooLateToInitUI to true and we don't send AppStart Trace.
+   */
+  private boolean isTooLateToInitUI = false;
+
+  private Timer appStartTime = null;
+  private Timer onCreateTime = null;
+  private Timer onStartTime = null;
+  private Timer onResumeTime = null;
+
+  private PerfSession startSession;
+  private boolean isStartedFromBackground = false;
 
   /**
    * Called from onCreate() method of an activity by instrumented byte code.
@@ -94,41 +130,29 @@ static AppStartTrace getInstance(TransportManager transportManager, Clock clock)
     if (instance == null) {
       synchronized (AppStartTrace.class) {
         if (instance == null) {
-          instance = new AppStartTrace(transportManager, clock);
+          instance =
+              new AppStartTrace(
+                  transportManager,
+                  clock,
+                  new ThreadPoolExecutor(
+                      CORE_POOL_SIZE,
+                      MAX_POOL_SIZE,
+                      /* keepAliveTime= */ MAX_LATENCY_BEFORE_UI_INIT + 10,
+                      TimeUnit.SECONDS,
+                      new LinkedBlockingQueue<>(1)));
         }
       }
     }
     return instance;
   }
 
-  private boolean isRegisteredForLifecycleCallbacks = false;
-  private final TransportManager transportManager;
-  private final Clock clock;
-  private Context appContext;
-  /**
-   * The first time onCreate() of any activity is called, the activity is saved as launchActivity.
-   */
-  private WeakReference<Activity> launchActivity;
-  /**
-   * The first time onResume() of any activity is called, the activity is saved as appStartActivity
-   */
-  private WeakReference<Activity> appStartActivity;
-
-  /**
-   * If the time difference between app starts and creation of any Activity is larger than
-   * MAX_LATENCY_BEFORE_UI_INIT, set mTooLateToInitUI to true and we don't send AppStart Trace.
-   */
-  private boolean isTooLateToInitUI = false;
-
-  private Timer onCreateTime = null;
-  private Timer onStartTime = null;
-  private Timer onResumeTime = null;
-
-  private boolean isStartedFromBackground = false;
-
-  AppStartTrace(@NonNull TransportManager transportManager, @NonNull Clock clock) {
+  AppStartTrace(
+      @NonNull TransportManager transportManager,
+      @NonNull Clock clock,
+      @NonNull ExecutorService executorService) {
     this.transportManager = transportManager;
     this.clock = clock;
+    this.executorService = executorService;
   }
 
   /** Called from FirebasePerfProvider to register this callback. */
@@ -191,51 +215,57 @@ public synchronized void onActivityResumed(Activity activity) {
     appStartActivity = new WeakReference<Activity>(activity);
 
     onResumeTime = clock.getTime();
-    final Timer startTime = FirebasePerfProvider.getAppStartTime();
+    this.appStartTime = FirebasePerfProvider.getAppStartTime();
+    this.startSession = SessionManager.getInstance().perfSession();
     AndroidLogger.getInstance()
         .debug(
             "onResume(): "
                 + activity.getClass().getName()
                 + ": "
-                + startTime.getDurationMicros(onResumeTime)
+                + this.appStartTime.getDurationMicros(onResumeTime)
                 + " microseconds");
 
+    // Log the app start trace in a non-main thread.
+    executorService.execute(this::logAppStartTrace);
+
+    if (isRegisteredForLifecycleCallbacks) {
+      // After AppStart trace is logged, we can unregister this callback.
+      unregisterActivityLifecycleCallbacks();
+    }
+  }
+
+  private void logAppStartTrace() {
     TraceMetric.Builder metric =
         TraceMetric.newBuilder()
             .setName(Constants.TraceNames.APP_START_TRACE_NAME.toString())
-            .setClientStartTimeUs(startTime.getMicros())
-            .setDurationUs(startTime.getDurationMicros(onResumeTime));
+            .setClientStartTimeUs(getappStartTime().getMicros())
+            .setDurationUs(getappStartTime().getDurationMicros(onResumeTime));
     List<TraceMetric> subtraces = new ArrayList<>(/* initialCapacity= */ 3);
 
-    TraceMetric.Builder temp =
+    TraceMetric.Builder traceMetricBuilder =
         TraceMetric.newBuilder()
             .setName(Constants.TraceNames.ON_CREATE_TRACE_NAME.toString())
-            .setClientStartTimeUs(startTime.getMicros())
-            .setDurationUs(startTime.getDurationMicros(onCreateTime));
-    subtraces.add(temp.build());
+            .setClientStartTimeUs(getappStartTime().getMicros())
+            .setDurationUs(getappStartTime().getDurationMicros(onCreateTime));
+    subtraces.add(traceMetricBuilder.build());
 
-    temp = TraceMetric.newBuilder();
-    temp.setName(Constants.TraceNames.ON_START_TRACE_NAME.toString())
+    traceMetricBuilder = TraceMetric.newBuilder();
+    traceMetricBuilder
+        .setName(Constants.TraceNames.ON_START_TRACE_NAME.toString())
         .setClientStartTimeUs(onCreateTime.getMicros())
         .setDurationUs(onCreateTime.getDurationMicros(onStartTime));
-    subtraces.add(temp.build());
+    subtraces.add(traceMetricBuilder.build());
 
-    temp = TraceMetric.newBuilder();
-    temp.setName(Constants.TraceNames.ON_RESUME_TRACE_NAME.toString())
+    traceMetricBuilder = TraceMetric.newBuilder();
+    traceMetricBuilder
+        .setName(Constants.TraceNames.ON_RESUME_TRACE_NAME.toString())
         .setClientStartTimeUs(onStartTime.getMicros())
         .setDurationUs(onStartTime.getDurationMicros(onResumeTime));
-    subtraces.add(temp.build());
+    subtraces.add(traceMetricBuilder.build());
 
-    metric
-        .addAllSubtraces(subtraces)
-        .addPerfSessions(SessionManager.getInstance().perfSession().build());
+    metric.addAllSubtraces(subtraces).addPerfSessions(this.startSession.build());
 
     transportManager.log(metric.build(), ApplicationProcessState.FOREGROUND_BACKGROUND);
-
-    if (isRegisteredForLifecycleCallbacks) {
-      // After AppStart trace is logged, we can unregister this callback.
-      unregisterActivityLifecycleCallbacks();
-    }
   }
 
   @Override
@@ -285,6 +315,11 @@ Activity getAppStartActivity() {
     return appStartActivity.get();
   }
 
+  @VisibleForTesting
+  Timer getappStartTime() {
+    return appStartTime;
+  }
+
   @VisibleForTesting
   Timer getOnCreateTime() {
     return onCreateTime;

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

@@ -33,6 +33,7 @@
 import com.google.firebase.perf.util.Timer;
 import com.google.firebase.perf.v1.ApplicationProcessState;
 import com.google.firebase.perf.v1.TraceMetric;
+import com.google.testing.timing.FakeScheduledExecutorService;
 import java.util.concurrent.TimeUnit;
 import org.junit.Assert;
 import org.junit.Before;
@@ -87,15 +88,18 @@ public Timer answer(InvocationOnMock invocationOnMock) throws Throwable {
   /** Test activity sequentially goes through onCreate()->onStart()->onResume() state change. */
   @Test
   public void testLaunchActivity() {
-    AppStartTrace trace = new AppStartTrace(transportManager, clock);
+    FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
+    AppStartTrace trace = new AppStartTrace(transportManager, clock, fakeExecutorService);
     // first activity goes through onCreate()->onStart()->onResume() state change.
     currentTime = 1;
     trace.onActivityCreated(activity1, bundle);
     currentTime = 2;
     trace.onActivityStarted(activity1);
     currentTime = 3;
     trace.onActivityResumed(activity1);
+    fakeExecutorService.runAll();
     verifyFinalState(activity1, trace, 1, 2, 3);
+
     // same activity goes through onCreate()->onStart()->onResume() state change again.
     // should have no effect on AppStartTrace.
     currentTime = 4;
@@ -104,6 +108,7 @@ public void testLaunchActivity() {
     trace.onActivityStarted(activity1);
     currentTime = 6;
     trace.onActivityResumed(activity1);
+    fakeExecutorService.runAll();
     verifyFinalState(activity1, trace, 1, 2, 3);
 
     // a different activity goes through onCreate()->onStart()->onResume() state change.
@@ -114,6 +119,7 @@ public void testLaunchActivity() {
     trace.onActivityStarted(activity2);
     currentTime = 9;
     trace.onActivityResumed(activity2);
+    fakeExecutorService.runAll();
     verifyFinalState(activity1, trace, 1, 2, 3);
   }
 
@@ -158,7 +164,8 @@ private void verifyFinalState(
    */
   @Test
   public void testInterleavedActivity() {
-    AppStartTrace trace = new AppStartTrace(transportManager, clock);
+    FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
+    AppStartTrace trace = new AppStartTrace(transportManager, clock, fakeExecutorService);
     // first activity onCreate()
     currentTime = 1;
     trace.onActivityCreated(activity1, bundle);
@@ -178,19 +185,22 @@ public void testInterleavedActivity() {
     trace.onActivityResumed(activity2);
     Assert.assertEquals(activity1, trace.getLaunchActivity());
     Assert.assertEquals(activity2, trace.getAppStartActivity());
+    fakeExecutorService.runAll();
     verifyFinalState(activity2, trace, 1, 3, 4);
 
     // first activity continues.
     currentTime = 5;
     trace.onActivityStarted(activity1);
     currentTime = 6;
     trace.onActivityResumed(activity1);
+    fakeExecutorService.runAll();
     verifyFinalState(activity2, trace, 1, 3, 4);
   }
 
   @Test
   public void testDelayedAppStart() {
-    AppStartTrace trace = new AppStartTrace(transportManager, clock);
+    FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
+    AppStartTrace trace = new AppStartTrace(transportManager, clock, fakeExecutorService);
     // Delays activity creation after 1 minute from app start time.
     currentTime = appStartTime + TimeUnit.MINUTES.toMicros(1) + 1;
     trace.onActivityCreated(activity1, bundle);
@@ -210,7 +220,8 @@ public void testDelayedAppStart() {
 
   @Test
   public void testStartFromBackground() {
-    AppStartTrace trace = new AppStartTrace(transportManager, clock);
+    FakeScheduledExecutorService fakeExecutorService = new FakeScheduledExecutorService();
+    AppStartTrace trace = new AppStartTrace(transportManager, clock, fakeExecutorService);
     trace.setIsStartFromBackground();
     trace.onActivityCreated(activity1, bundle);
     Assert.assertNull(trace.getOnCreateTime());