[Fireperf][AASA] Additional experiments for _experiment_as_ttid

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,13 +210,68 @@ private void recordFirstDrawDone() {
     if (firstDrawDone != null) {
       return;
     }
+    Timer start = getStartTimer();
     this.firstDrawDone = clock.getTime();
-    executorService.execute(
-        () -> this.logColdStart(getStartTimer(), this.firstDrawDone, this.startSession));
+    int subtraceCount = this.experimentTtid.getSubtracesCount();
+    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 (subtraceCount > 0) {
+      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();
+    int subtraceCount = this.experimentTtid.getSubtracesCount();
+    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 (subtraceCount > 0) {
+      executorService.execute(() -> this.logExperimentTtid(this.experimentTtid));
+
+      if (isRegisteredForLifecycleCallbacks) {
+        // After AppStart trace is queued to be logged, we can unregister this callback.
+        unregisterActivityLifecycleCallbacks();
+      }
     }
   }
 
@@ -252,6 +312,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 +341,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);
   }
 

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

@@ -23,10 +23,7 @@
 
 /**
  * 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 {

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

@@ -0,0 +1,51 @@
+// 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;
+
+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 onDraw past the first is a no-op
+    View view = viewReference.getAndSet(null);
+    if (view == null) {
+      return true;
+    }
+    // OnDrawListeners cannot be removed within onDraw, so we remove it with a
+    // GlobalLayoutListener
+    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,11 +115,11 @@ 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 */
@@ -144,6 +155,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 +187,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/util/TimerTest.java

@@ -53,8 +53,8 @@ public void ofElapsedRealtime_createsNewTimerWithArgumentElapsedRealtime() {
     // Robolectric shadows SystemClock, which is paused and can only change via specific methods.
     long refElapsedRealtime = SystemClock.elapsedRealtime();
     Timer ref = new Timer();
-    Timer past = Timer.ofElapsedRealtime(refElapsedRealtime - 100);
-    Timer future = Timer.ofElapsedRealtime(refElapsedRealtime + 100);
+    Timer past = Timer.ofElapsedRealtime(refElapsedRealtime - 100, 0);
+    Timer future = Timer.ofElapsedRealtime(refElapsedRealtime + 100, 0);
 
     assertThat(past.getDurationMicros(ref)).isEqualTo(MILLISECONDS.toMicros(100));
     assertThat(ref.getDurationMicros(future)).isEqualTo(MILLISECONDS.toMicros(100));
@@ -67,10 +67,10 @@ public void ofElapsedRealtime_extrapolatesWallTime() {
     ShadowSystemClock.advanceBy(Duration.ofMillis(10000000));
     long nowElapsedRealtime = SystemClock.elapsedRealtime();
     Timer now = new Timer();
-    Timer morePast = Timer.ofElapsedRealtime(nowElapsedRealtime - 2000);
-    Timer past = Timer.ofElapsedRealtime(nowElapsedRealtime - 1000);
-    Timer future = Timer.ofElapsedRealtime(nowElapsedRealtime + 1000);
-    Timer moreFuture = Timer.ofElapsedRealtime(nowElapsedRealtime + 2000);
+    Timer morePast = Timer.ofElapsedRealtime(nowElapsedRealtime - 2000, 0);
+    Timer past = Timer.ofElapsedRealtime(nowElapsedRealtime - 1000, 0);
+    Timer future = Timer.ofElapsedRealtime(nowElapsedRealtime + 1000, 0);
+    Timer moreFuture = Timer.ofElapsedRealtime(nowElapsedRealtime + 2000, 0);
 
     // We cannot manipulate System.currentTimeMillis() so multiple comparisons are used to test
     assertThat(morePast.getMicros()).isLessThan(past.getMicros());
@@ -103,7 +103,7 @@ public void testReset() throws InterruptedException {
 
   @Test
   public void testGetCurrentTimestampMicros() {
-    Timer timer = new Timer(0, 0);
+    Timer timer = new Timer(0, 0, 0);
     long currentTimeSmallest = timer.getCurrentTimestampMicros();
 
     assertThat(timer.getMicros()).isEqualTo(0);
@@ -112,7 +112,7 @@ public void testGetCurrentTimestampMicros() {
 
   @Test
   public void testParcel() {
-    Timer timer1 = new Timer(1000, 1000000);
+    Timer timer1 = new Timer(1000, 1000000, 1000000);
 
     Parcel p1 = Parcel.obtain();
     timer1.writeToParcel(p1, 0);
@@ -132,6 +132,6 @@ public void testParcel() {
 
   /** Helper for other tests that returns elapsedRealtimeMicros from a Timer object */
   public static long getElapsedRealtimeMicros(Timer timer) {
-    return new Timer(0, 0).getDurationMicros(timer);
+    return new Timer(0, 0, 0).getDurationMicros(timer);
   }
 }