[Fireperf][AASA] Additional experiments for _experiment_as_ttid (#4283)

* predraw and uptimeMillis

* fix send event

* fix dangling variable and naming

* copyright

* fix test

* onStop

* test

* better readability

* comments

* reduce code

* reset

Author: leotianlizhan

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

@@ -35,6 +35,7 @@
 import com.google.firebase.perf.util.Clock;
 import com.google.firebase.perf.util.Constants;
 import com.google.firebase.perf.util.FirstDrawDoneListener;
+import com.google.firebase.perf.util.PreDrawListener;
 import com.google.firebase.perf.util.Timer;
 import com.google.firebase.perf.v1.ApplicationProcessState;
 import com.google.firebase.perf.v1.TraceMetric;
@@ -75,6 +76,7 @@ public class AppStartTrace implements ActivityLifecycleCallbacks {
   private final TransportManager transportManager;
   private final Clock clock;
   private final ConfigResolver configResolver;
+  private final TraceMetric.Builder experimentTtid;
   private Context appContext;
   /**
    * The first time onCreate() of any activity is called, the activity is saved as launchActivity.
@@ -96,6 +98,7 @@ public class AppStartTrace implements ActivityLifecycleCallbacks {
   private Timer onStartTime = null;
   private Timer onResumeTime = null;
   private Timer firstDrawDone = null;
+  private Timer preDraw = null;
 
   private PerfSession startSession;
   private boolean isStartedFromBackground = false;
@@ -163,6 +166,7 @@ static AppStartTrace getInstance(TransportManager transportManager, Clock clock)
     this.clock = clock;
     this.configResolver = configResolver;
     this.executorService = executorService;
+    this.experimentTtid = TraceMetric.newBuilder().setName("_experiment_app_start_ttid");
   }
 
   /** Called from FirebasePerfProvider to register this callback. */
@@ -196,7 +200,8 @@ public synchronized void unregisterActivityLifecycleCallbacks() {
    */
   private static Timer getStartTimer() {
     if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.N) {
-      return Timer.ofElapsedRealtime(Process.getStartElapsedRealtime());
+      return Timer.ofElapsedRealtime(
+          Process.getStartElapsedRealtime(), Process.getStartUptimeMillis());
     }
     return FirebasePerfProvider.getAppStartTime();
   }
@@ -205,16 +210,73 @@ private void recordFirstDrawDone() {
     if (firstDrawDone != null) {
       return;
     }
+    Timer start = getStartTimer();
     this.firstDrawDone = clock.getTime();
-    executorService.execute(
-        () -> this.logColdStart(getStartTimer(), this.firstDrawDone, this.startSession));
+    this.experimentTtid
+        .setClientStartTimeUs(start.getMicros())
+        .setDurationUs(start.getDurationMicros(this.firstDrawDone));
 
-    if (isRegisteredForLifecycleCallbacks) {
-      // After AppStart trace is queued to be logged, we can unregister this callback.
-      unregisterActivityLifecycleCallbacks();
+    TraceMetric.Builder subtrace =
+        TraceMetric.newBuilder()
+            .setName("_experiment_classLoadTime")
+            .setClientStartTimeUs(FirebasePerfProvider.getAppStartTime().getMicros())
+            .setDurationUs(
+                FirebasePerfProvider.getAppStartTime().getDurationMicros(this.firstDrawDone));
+    this.experimentTtid.addSubtraces(subtrace.build());
+
+    subtrace = TraceMetric.newBuilder();
+    subtrace
+        .setName("_experiment_uptimeMillis")
+        .setClientStartTimeUs(start.getMicros())
+        .setDurationUs(start.getDurationUptimeMicros(this.firstDrawDone));
+    this.experimentTtid.addSubtraces(subtrace.build());
+
+    this.experimentTtid.addPerfSessions(this.startSession.build());
+
+    if (isExperimentTraceDone()) {
+      executorService.execute(() -> this.logExperimentTtid(this.experimentTtid));
+
+      if (isRegisteredForLifecycleCallbacks) {
+        // After AppStart trace is queued to be logged, we can unregister this callback.
+        unregisterActivityLifecycleCallbacks();
+      }
     }
   }
 
+  private void recordFirstDrawDonePreDraw() {
+    if (preDraw != null) {
+      return;
+    }
+    Timer start = getStartTimer();
+    this.preDraw = clock.getTime();
+    TraceMetric.Builder subtrace =
+        TraceMetric.newBuilder()
+            .setName("_experiment_preDraw")
+            .setClientStartTimeUs(start.getMicros())
+            .setDurationUs(start.getDurationMicros(this.preDraw));
+    this.experimentTtid.addSubtraces(subtrace.build());
+
+    subtrace = TraceMetric.newBuilder();
+    subtrace
+        .setName("_experiment_preDraw_uptimeMillis")
+        .setClientStartTimeUs(start.getMicros())
+        .setDurationUs(start.getDurationUptimeMicros(this.preDraw));
+    this.experimentTtid.addSubtraces(subtrace.build());
+
+    if (isExperimentTraceDone()) {
+      executorService.execute(() -> this.logExperimentTtid(this.experimentTtid));
+
+      if (isRegisteredForLifecycleCallbacks) {
+        // After AppStart trace is queued to be logged, we can unregister this callback.
+        unregisterActivityLifecycleCallbacks();
+      }
+    }
+  }
+
+  private boolean isExperimentTraceDone() {
+    return this.preDraw != null && this.firstDrawDone != null;
+  }
+
   @Override
   public synchronized void onActivityCreated(Activity activity, Bundle savedInstanceState) {
     if (isStartedFromBackground || onCreateTime != null // An activity already called onCreate()
@@ -252,6 +314,7 @@ public synchronized void onActivityResumed(Activity activity) {
     if (isExperimentTTIDEnabled) {
       View rootView = activity.findViewById(android.R.id.content);
       FirstDrawDoneListener.registerForNextDraw(rootView, this::recordFirstDrawDone);
+      PreDrawListener.registerForNextDraw(rootView, this::recordFirstDrawDonePreDraw);
     }
 
     if (onResumeTime != null) { // An activity already called onResume()
@@ -280,21 +343,7 @@ public synchronized void onActivityResumed(Activity activity) {
     }
   }
 
-  private void logColdStart(Timer start, Timer end, PerfSession session) {
-    TraceMetric.Builder metric =
-        TraceMetric.newBuilder()
-            .setName("_experiment_app_start_ttid")
-            .setClientStartTimeUs(start.getMicros())
-            .setDurationUs(start.getDurationMicros(end));
-
-    TraceMetric.Builder subtrace =
-        TraceMetric.newBuilder()
-            .setName("_experiment_classLoadTime")
-            .setClientStartTimeUs(FirebasePerfProvider.getAppStartTime().getMicros())
-            .setDurationUs(FirebasePerfProvider.getAppStartTime().getDurationMicros(end));
-
-    metric.addSubtraces(subtrace).addPerfSessions(this.startSession.build());
-
+  private void logExperimentTtid(TraceMetric.Builder metric) {
     transportManager.log(metric.build(), ApplicationProcessState.FOREGROUND_BACKGROUND);
   }
 
@@ -333,10 +382,32 @@ private void logAppStartTrace() {
   }
 
   @Override
-  public void onActivityPaused(Activity activity) {}
+  public void onActivityPaused(Activity activity) {
+    if (isExperimentTraceDone()) {
+      return;
+    }
+    Timer onPauseTime = clock.getTime();
+    TraceMetric.Builder subtrace =
+        TraceMetric.newBuilder()
+            .setName("_experiment_onPause")
+            .setClientStartTimeUs(onPauseTime.getMicros())
+            .setDurationUs(getStartTimer().getDurationMicros(onPauseTime));
+    this.experimentTtid.addSubtraces(subtrace.build());
+  }
 
   @Override
-  public synchronized void onActivityStopped(Activity activity) {}
+  public void onActivityStopped(Activity activity) {
+    if (isExperimentTraceDone()) {
+      return;
+    }
+    Timer onStopTime = clock.getTime();
+    TraceMetric.Builder subtrace =
+        TraceMetric.newBuilder()
+            .setName("_experiment_onStop")
+            .setClientStartTimeUs(onStopTime.getMicros())
+            .setDurationUs(getStartTimer().getDurationMicros(onStopTime));
+    this.experimentTtid.addSubtraces(subtrace.build());
+  }
 
   @Override
   public void onActivityDestroyed(Activity activity) {}

firebase-perf/src/main/java/com/google/firebase/perf/util/FirstDrawDoneListener.java

@@ -18,17 +18,12 @@
 import android.os.Looper;
 import android.view.View;
 import android.view.ViewTreeObserver;
-import androidx.annotation.RequiresApi;
 import java.util.concurrent.atomic.AtomicReference;
 
 /**
  * OnDrawListener that unregisters itself and invokes callback when the next draw is done. This API
- * 16+ implementation is an approximation of the initial display time. {@link
- * android.view.Choreographer#postFrameCallback} is an Android API that provides a simpler and more
- * accurate initial display time, but it was bugged before API 30, hence we use this backported
- * implementation.
+ * 16+ implementation is an approximation of the initial-display-time defined by Android Vitals.
  */
-@RequiresApi(Build.VERSION_CODES.JELLY_BEAN)
 public class FirstDrawDoneListener implements ViewTreeObserver.OnDrawListener {
   private final Handler mainThreadHandler = new Handler(Looper.getMainLooper());
   private final AtomicReference<View> viewReference;

firebase-perf/src/main/java/com/google/firebase/perf/util/PreDrawListener.java

@@ -0,0 +1,53 @@
+// Copyright 2022 Google LLC
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+//
+// You may obtain a copy of the License at
+//      http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+package com.google.firebase.perf.util;
+
+import android.os.Handler;
+import android.os.Looper;
+import android.view.View;
+import android.view.ViewTreeObserver;
+import java.util.concurrent.atomic.AtomicReference;
+
+/**
+ * OnPreDraw listener that unregisters itself and post a callback to the main thread during
+ * OnPreDraw. This is an approximation of the initial-display time defined by Android Vitals.
+ */
+public class PreDrawListener implements ViewTreeObserver.OnPreDrawListener {
+  private final Handler mainThreadHandler = new Handler(Looper.getMainLooper());
+  private final AtomicReference<View> viewReference;
+  private final Runnable callback;
+
+  /** Registers a post-draw callback for the next draw of a view. */
+  public static void registerForNextDraw(View view, Runnable drawDoneCallback) {
+    final PreDrawListener listener = new PreDrawListener(view, drawDoneCallback);
+    view.getViewTreeObserver().addOnPreDrawListener(listener);
+  }
+
+  private PreDrawListener(View view, Runnable callback) {
+    this.viewReference = new AtomicReference<>(view);
+    this.callback = callback;
+  }
+
+  @Override
+  public boolean onPreDraw() {
+    // Set viewReference to null so any onPreDraw past the first is a no-op
+    View view = viewReference.getAndSet(null);
+    if (view == null) {
+      return true;
+    }
+    view.getViewTreeObserver().removeOnPreDrawListener(this);
+    mainThreadHandler.post(callback);
+    return true;
+  }
+}

firebase-perf/src/main/java/com/google/firebase/perf/util/Timer.java

@@ -43,17 +43,23 @@ public class Timer implements Parcelable {
    * compute duration between 2 timestamps in the same timebase. It is NOT wall-clock time.
    */
   private long elapsedRealtimeMicros;
+  /**
+   * Monotonic time measured in the {@link SystemClock#uptimeMillis()} timebase. Only used to
+   * compute duration between 2 timestamps in the same timebase. It is NOT wall-clock time.
+   */
+  private long uptimeMicros;
 
   /**
    * Returns a new Timer object as if it was stamped at the given elapsedRealtime. Uses current
    * wall-clock as a reference to extrapolate the wall-clock at the given elapsedRealtime.
    *
    * @param elapsedRealtimeMillis timestamp in the {@link SystemClock#elapsedRealtime()} timebase
    */
-  public static Timer ofElapsedRealtime(final long elapsedRealtimeMillis) {
+  public static Timer ofElapsedRealtime(final long elapsedRealtimeMillis, final long uptimeMillis) {
+    long uptimeMicros = MILLISECONDS.toMicros(uptimeMillis);
     long elapsedRealtimeMicros = MILLISECONDS.toMicros(elapsedRealtimeMillis);
     long wallClockMicros = wallClockMicros() + (elapsedRealtimeMicros - elapsedRealtimeMicros());
-    return new Timer(wallClockMicros, elapsedRealtimeMicros);
+    return new Timer(wallClockMicros, elapsedRealtimeMicros, uptimeMicros);
   }
 
   /**
@@ -77,10 +83,14 @@ private static long elapsedRealtimeMicros() {
     return MILLISECONDS.toMicros(SystemClock.elapsedRealtime());
   }
 
+  private static long uptimeMicros() {
+    return MILLISECONDS.toMicros(SystemClock.uptimeMillis());
+  }
+
   // TODO: make all constructors private, use public static factory methods, per Effective Java
   /** Construct Timer object using System clock. */
   public Timer() {
-    this(wallClockMicros(), elapsedRealtimeMicros());
+    this(wallClockMicros(), elapsedRealtimeMicros(), uptimeMicros());
   }
 
   /**
@@ -91,9 +101,10 @@ public Timer() {
    *     SystemClock#elapsedRealtime()} timebase
    */
   @VisibleForTesting
-  Timer(long epochMicros, long elapsedRealtimeMicros) {
+  Timer(long epochMicros, long elapsedRealtimeMicros, long uptimeMicros) {
     this.wallClockMicros = epochMicros;
     this.elapsedRealtimeMicros = elapsedRealtimeMicros;
+    this.uptimeMicros = uptimeMicros;
   }
 
   /**
@@ -104,18 +115,19 @@ public Timer() {
    */
   @VisibleForTesting
   public Timer(long testTime) {
-    this(testTime, testTime);
+    this(testTime, testTime, testTime);
   }
 
   private Timer(Parcel in) {
-    this(in.readLong(), in.readLong());
+    this(in.readLong(), in.readLong(), in.readLong());
   }
 
   /** resets the start time */
   public void reset() {
     // TODO: consider removing this method and make Timer immutable thus fully thread-safe
     wallClockMicros = wallClockMicros();
     elapsedRealtimeMicros = elapsedRealtimeMicros();
+    uptimeMicros = uptimeMicros();
   }
 
   /** Return wall-clock time in microseconds. */
@@ -144,6 +156,16 @@ public long getDurationMicros(@NonNull final Timer end) {
     return end.elapsedRealtimeMicros - this.elapsedRealtimeMicros;
   }
 
+  /**
+   * Calculate duration in microseconds using uptime. The start time is this Timer object.
+   *
+   * @param end end Timer object
+   * @return duration in microseconds.
+   */
+  public long getDurationUptimeMicros(@NonNull final Timer end) {
+    return end.uptimeMicros - this.uptimeMicros;
+  }
+
   /**
    * Calculates the current wall clock off the existing wall clock time. The reason this is better
    * instead of just doing System.getCurrentTimeMillis is that the device time could've changed
@@ -166,6 +188,7 @@ public long getCurrentTimestampMicros() {
   public void writeToParcel(Parcel out, int flags) {
     out.writeLong(wallClockMicros);
     out.writeLong(elapsedRealtimeMicros);
+    out.writeLong(uptimeMicros);
   }
 
   /**

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

@@ -298,13 +298,19 @@ public void timeToInitialDisplay_isLogged() {
     trace.onActivityCreated(activity1, bundle);
     trace.onActivityStarted(activity1);
     trace.onActivityResumed(activity1);
+    // Experiment: simulate backgrounding before draw
+    trace.onActivityPaused(activity1);
+    trace.onActivityStopped(activity1);
+    trace.onActivityStarted(activity1);
+    trace.onActivityResumed(activity1);
     fakeExecutorService.runAll();
     verify(transportManager, times(1))
         .log(isA(TraceMetric.class), isA(ApplicationProcessState.class));
 
     // Simulate draw and manually stepping time forward
     ShadowSystemClock.advanceBy(Duration.ofMillis(1000));
     long drawTime = TimeUnit.NANOSECONDS.toMicros(SystemClock.elapsedRealtimeNanos());
+    testView.getViewTreeObserver().dispatchOnPreDraw();
     testView.getViewTreeObserver().dispatchOnDraw();
     shadowOf(Looper.getMainLooper()).idle();
     fakeExecutorService.runNext();
@@ -317,5 +323,6 @@ public void timeToInitialDisplay_isLogged() {
     assertThat(ttid.getName()).isEqualTo("_experiment_app_start_ttid");
     assertThat(ttid.getDurationUs()).isNotEqualTo(resumeTime - appStartTime);
     assertThat(ttid.getDurationUs()).isEqualTo(drawTime - appStartTime);
+    assertThat(ttid.getSubtracesCount()).isEqualTo(6);
   }
 }