Merge d2b9225 into f5c9e3b

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

@@ -14,92 +14,134 @@
 
 package com.google.firebase.perf.util;
 
+import static java.util.concurrent.TimeUnit.MILLISECONDS;
+import static java.util.concurrent.TimeUnit.NANOSECONDS;
+
+import android.os.Build;
 import android.os.Parcel;
 import android.os.Parcelable;
+import android.os.SystemClock;
 import androidx.annotation.NonNull;
 import com.google.android.gms.common.util.VisibleForTesting;
-import java.util.concurrent.TimeUnit;
 
-/** A Timer class provides both wall-clock (epoch) time and high resolution time (nano time). */
+/**
+ * A Timer class provides both wall-clock (epoch) time and monotonic time (elapsedRealtime).
+ * Timestamps are captured with millisecond-precision, because that's the time unit most widely
+ * available in Android APIs. However, private fields and public method returns are in microseconds
+ * due to Fireperf proto requirements.
+ */
 public class Timer implements Parcelable {
 
-  /** Wall-clock time or epoch time in microseconds, */
-  private long timeInMicros;
   /**
-   * High resolution time in nanoseconds. High resolution time should only be used to calculate
-   * duration or latency. It is not wall-clock time.
+   * Wall-clock time or epoch time in microseconds. Do NOT use for duration because wall-clock is
+   * not guaranteed to be monotonic: it can be set by the user or the phone network, thus it may
+   * jump forwards or backwards unpredictably. {@see SystemClock}
+   */
+  private long wallClockMicros;
+  /**
+   * Monotonic time measured in the {@link SystemClock#elapsedRealtime()} timebase. Only used to
+   * compute duration between 2 timestamps in the same timebase. It is NOT wall-clock time.
+   */
+  private long elapsedRealtimeMicros;
+
+  /**
+   * 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) {
+    long elapsedRealtimeMicros = MILLISECONDS.toMicros(elapsedRealtimeMillis);
+    long wallClockMicros = wallClockMicros() + (elapsedRealtimeMicros - elapsedRealtimeMicros());
+    return new Timer(wallClockMicros, elapsedRealtimeMicros);
+  }
+
+  /**
+   * Helper to get current wall-clock time from system API.
+   *
+   * @return wall-clock time in microseconds.
    */
-  private long highResTime;
+  private static long wallClockMicros() {
+    return MILLISECONDS.toMicros(System.currentTimeMillis());
+  }
 
   /**
-   * Construct Timer object using System clock. Make it package visible to be only accessible from
-   * com.google.firebase.perf.util.Clock.
+   * Helper to get current {@link SystemClock#elapsedRealtime()} from system API.
+   *
+   * @return wall-clock time in microseconds.
    */
+  private static long elapsedRealtimeMicros() {
+    if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.JELLY_BEAN_MR1) {
+      return NANOSECONDS.toMicros(SystemClock.elapsedRealtimeNanos());
+    }
+    return MILLISECONDS.toMicros(SystemClock.elapsedRealtime());
+  }
+
+  // TODO: make all constructors private, use public static factory methods, per Effective Java
+  /** Construct Timer object using System clock. */
   public Timer() {
-    timeInMicros = TimeUnit.MILLISECONDS.toMicros(System.currentTimeMillis());
-    highResTime = System.nanoTime();
+    this(wallClockMicros(), elapsedRealtimeMicros());
   }
 
   /**
-   * Construct a Timer object with input wall-clock time, assume high resolution time is same as
-   * wall-clock time.
+   * Construct a Timer object with input wall-clock time and elapsedRealtime.
    *
-   * @param time wall-clock time in microseconds
+   * @param epochMicros wall-clock time in milliseconds since epoch
+   * @param elapsedRealtimeMicros monotonic time in microseconds in the {@link
+   *     SystemClock#elapsedRealtime()} timebase
    */
   @VisibleForTesting
-  public Timer(long time) {
-    this.timeInMicros = time;
-    highResTime = TimeUnit.MICROSECONDS.toNanos(time);
+  Timer(long epochMicros, long elapsedRealtimeMicros) {
+    this.wallClockMicros = epochMicros;
+    this.elapsedRealtimeMicros = elapsedRealtimeMicros;
   }
 
   /**
-   * Construct a Timer object with input wall-clock time and high resolution time.
+   * TEST-ONLY constructor that sets both wall-clock time and elapsedRealtime to the same input
+   * value. Do NOT use this for any real logic because this is mixing 2 different time-bases.
    *
-   * @param time wall-clock time in microseconds
-   * @param highResTime high resolution time in nanoseconds
+   * @param testTime value to set both wall-clock and elapsedRealtime to for testing purposes
    */
   @VisibleForTesting
-  public Timer(long time, long highResTime) {
-    this.timeInMicros = time;
-    this.highResTime = highResTime;
+  public Timer(long testTime) {
+    this(testTime, testTime);
   }
 
   private Timer(Parcel in) {
-    timeInMicros = in.readLong();
-    highResTime = in.readLong();
+    this(in.readLong(), in.readLong());
   }
 
   /** resets the start time */
   public void reset() {
-    timeInMicros = TimeUnit.MILLISECONDS.toMicros(System.currentTimeMillis());
-    highResTime = System.nanoTime();
+    // TODO: consider removing this method and make Timer immutable thus fully thread-safe
+    wallClockMicros = wallClockMicros();
+    elapsedRealtimeMicros = elapsedRealtimeMicros();
   }
 
   /** Return wall-clock time in microseconds. */
   public long getMicros() {
-    return timeInMicros;
+    return wallClockMicros;
   }
 
   /**
-   * Calculate duration in microseconds using the the high resolution time.
+   * Calculate duration in microseconds using elapsedRealtime.
    *
    * <p>The start time is this Timer object, end time is current time.
    *
    * @return duration in microseconds.
    */
   public long getDurationMicros() {
-    return TimeUnit.NANOSECONDS.toMicros(System.nanoTime() - this.highResTime);
+    return getDurationMicros(new Timer());
   }
 
   /**
-   * Calculate duration in microseconds using the the high resolution time. The start time is this
-   * Timer object.
+   * Calculate duration in microseconds using elapsedRealtime. The start time is this Timer object.
    *
    * @param end end Timer object
    * @return duration in microseconds.
    */
   public long getDurationMicros(@NonNull final Timer end) {
-    return TimeUnit.NANOSECONDS.toMicros(end.highResTime - this.highResTime);
+    return end.elapsedRealtimeMicros - this.elapsedRealtimeMicros;
   }
 
   /**
@@ -111,17 +153,7 @@ public long getDurationMicros(@NonNull final Timer end) {
    *     was created.
    */
   public long getCurrentTimestampMicros() {
-    return timeInMicros + getDurationMicros();
-  }
-
-  /**
-   * Return high resolution time in microseconds, only useful for testing..
-   *
-   * @return high resolution time in microseconds.
-   */
-  @VisibleForTesting
-  public long getHighResTime() {
-    return TimeUnit.NANOSECONDS.toMicros(highResTime);
+    return wallClockMicros + getDurationMicros();
   }
 
   /**
@@ -132,8 +164,8 @@ public long getHighResTime() {
    * @param flags always will be the value 0.
    */
   public void writeToParcel(Parcel out, int flags) {
-    out.writeLong(timeInMicros);
-    out.writeLong(highResTime);
+    out.writeLong(wallClockMicros);
+    out.writeLong(elapsedRealtimeMicros);
   }
 
   /**

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

@@ -14,6 +14,7 @@
 
 package com.google.firebase.perf.metrics;
 
+import static com.google.firebase.perf.util.TimerTest.getElapsedRealtimeMicros;
 import static org.mockito.Mockito.doAnswer;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.times;
@@ -63,11 +64,8 @@ public class AppStartTraceTest extends FirebasePerformanceTestBase {
   // a mocked current wall-clock time in microseconds.
   private long currentTime = 0;
 
-  // wall-clock time in microseconds
-  private long appStartTime;
-
-  // high resolution time in microseconds
-  private long appStartHRT;
+  // Timer at the beginning of app startup
+  private Timer appStart;
 
   @Before
   public void setUp() {
@@ -83,8 +81,7 @@ public Timer answer(InvocationOnMock invocationOnMock) throws Throwable {
         .getTime();
     transportManager = mock(TransportManager.class);
     traceArgumentCaptor = ArgumentCaptor.forClass(TraceMetric.class);
-    appStartTime = FirebasePerfProvider.getAppStartTime().getMicros();
-    appStartHRT = FirebasePerfProvider.getAppStartTime().getHighResTime();
+    appStart = FirebasePerfProvider.getAppStartTime();
   }
 
   @After
@@ -144,14 +141,15 @@ private void verifyFinalState(
     TraceMetric metric = traceArgumentCaptor.getValue();
 
     Assert.assertEquals(Constants.TraceNames.APP_START_TRACE_NAME.toString(), metric.getName());
-    Assert.assertEquals(appStartTime, metric.getClientStartTimeUs());
-    Assert.assertEquals(resumeTime - appStartHRT, metric.getDurationUs());
+    Assert.assertEquals(appStart.getMicros(), metric.getClientStartTimeUs());
+    Assert.assertEquals(resumeTime - getElapsedRealtimeMicros(appStart), metric.getDurationUs());
 
     Assert.assertEquals(3, metric.getSubtracesCount());
     Assert.assertEquals(
         Constants.TraceNames.ON_CREATE_TRACE_NAME.toString(), metric.getSubtraces(0).getName());
-    Assert.assertEquals(appStartTime, metric.getSubtraces(0).getClientStartTimeUs());
-    Assert.assertEquals(createTime - appStartHRT, metric.getSubtraces(0).getDurationUs());
+    Assert.assertEquals(appStart.getMicros(), metric.getSubtraces(0).getClientStartTimeUs());
+    Assert.assertEquals(
+        createTime - getElapsedRealtimeMicros(appStart), metric.getSubtraces(0).getDurationUs());
 
     Assert.assertEquals(
         Constants.TraceNames.ON_START_TRACE_NAME.toString(), metric.getSubtraces(1).getName());
@@ -210,7 +208,7 @@ public void testDelayedAppStart() {
     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;
+    currentTime = appStart.getMicros() + TimeUnit.MINUTES.toMicros(1) + 1;
     trace.onActivityCreated(activity1, bundle);
     Assert.assertEquals(currentTime, trace.getOnCreateTime().getMicros());
     ++currentTime;

firebase-perf/src/test/java/com/google/firebase/perf/util/TimerTest.java

@@ -15,27 +15,75 @@
 package com.google.firebase.perf.util;
 
 import static com.google.common.truth.Truth.assertThat;
+import static java.util.concurrent.TimeUnit.MILLISECONDS;
 
 import android.os.Parcel;
-import java.util.concurrent.TimeUnit;
+import android.os.SystemClock;
+import java.time.Duration;
 import org.junit.Assert;
 import org.junit.Before;
 import org.junit.Test;
 import org.junit.runner.RunWith;
 import org.robolectric.RobolectricTestRunner;
-
-/** Unit tests for {@link Timer}. */
+import org.robolectric.shadows.ShadowSystemClock;
+
+/**
+ * Unit tests for {@link Timer}.
+ *
+ * <p>IMPORTANT: {@link SystemClock} is paused in tests, and can only be advanced through specific
+ * methods such as {@link ShadowSystemClock#advanceBy(Duration)} which are shadowed by Robolectic.
+ */
 @RunWith(RobolectricTestRunner.class)
 public class TimerTest {
 
   @Before
   public void setUp() {}
 
+  @Test
+  public void getDurationMicros_returnsDifferenceBetweenElapsedRealtime() {
+    // Robolectric shadows SystemClock, which is paused and can only change via specific methods.
+    Timer start = new Timer();
+    ShadowSystemClock.advanceBy(Duration.ofMillis(100000));
+    Timer end = new Timer();
+    assertThat(start.getDurationMicros(end)).isEqualTo(MILLISECONDS.toMicros(100000));
+  }
+
+  @Test
+  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);
+
+    assertThat(past.getDurationMicros(ref)).isEqualTo(MILLISECONDS.toMicros(100));
+    assertThat(ref.getDurationMicros(future)).isEqualTo(MILLISECONDS.toMicros(100));
+  }
+
+  @Test
+  public void ofElapsedRealtime_extrapolatesWallTime() {
+    // Robolectric shadows SystemClock, which is paused and can only change via specific methods.
+    // Advance SystemClock by a large amount to avoid negative time
+    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);
+
+    // We cannot manipulate System.currentTimeMillis() so multiple comparisons are used to test
+    assertThat(morePast.getMicros()).isLessThan(past.getMicros());
+    assertThat(past.getMicros()).isLessThan(now.getMicros());
+    assertThat(now.getMicros()).isLessThan(future.getMicros());
+    assertThat(future.getMicros()).isLessThan(moreFuture.getMicros());
+  }
+
   @Test
   public void testCreate() throws InterruptedException {
     Timer timer = new Timer();
     Thread.sleep(10);
-    long currentTimeMicros = TimeUnit.MILLISECONDS.toMicros(System.currentTimeMillis());
+    long currentTimeMicros = MILLISECONDS.toMicros(System.currentTimeMillis());
 
     assertThat(timer.getMicros()).isNotEqualTo(currentTimeMicros);
     assertThat(timer.getMicros()).isLessThan(currentTimeMicros);
@@ -45,7 +93,7 @@ public void testCreate() throws InterruptedException {
   public void testReset() throws InterruptedException {
     Timer timer = new Timer();
     Thread.sleep(10);
-    long currentTimeMicros = TimeUnit.MILLISECONDS.toMicros(System.currentTimeMillis());
+    long currentTimeMicros = MILLISECONDS.toMicros(System.currentTimeMillis());
 
     assertThat(timer.getMicros()).isNotEqualTo(currentTimeMicros);
     timer.reset();
@@ -55,7 +103,7 @@ public void testReset() throws InterruptedException {
 
   @Test
   public void testGetCurrentTimestampMicros() {
-    Timer timer = new Timer(0);
+    Timer timer = new Timer(0, 0);
     long currentTimeSmallest = timer.getCurrentTimestampMicros();
 
     assertThat(timer.getMicros()).isEqualTo(0);
@@ -76,9 +124,14 @@ public void testParcel() {
 
     Timer timer2 = Timer.CREATOR.createFromParcel(p2);
     Assert.assertEquals(timer1.getMicros(), timer2.getMicros());
-    Assert.assertEquals(timer1.getHighResTime(), timer2.getHighResTime());
+    Assert.assertEquals(timer1.getDurationMicros(timer2), 0);
 
     p1.recycle();
     p2.recycle();
   }
+
+  /** Helper for other tests that returns elapsedRealtimeMicros from a Timer object */
+  public static long getElapsedRealtimeMicros(Timer timer) {
+    return new Timer(0, 0).getDurationMicros(timer);
+  }
 }