[ScopedTaskEnvironment] Always mock TimeTicks::Now() under MOCK_TIME mode

This (PS1) passes all existing tests as-is but
ParkableStringTest.ReportTotalUnparkingTime.

This failure happens because samples of Now() within the same task
no longer have any delta under MOCK_TIME regardless of how CPU expensive
the operation actually is.

That test was using a state of the art approach, base::ElapsedTimer,
MOCK_TIME, base::HistogramTester, etc.

But base::ElaspedTimer is neutered by the change to MOCK_TIME in this CL.

There are two potential solutions:
  1) Have ElapsedTimer play a role in auto-advancing mock-time.
  2) Mock timings returned by ElpasedTimer.

(1) is undesirable because it would make it possible for delayed tasks
to run as part of a basic RunUntilIdle() which takes control of delayed
tasks away from the ScopedTaskEnvironment owner and is highly undesired.

(2) is more explicit but also easier to control. This CL does that by
adding base::ScopedMockElapsedTimersForTest.

This actually makes ParkableStringTest.ReportTotalUnparkingTime cleaner
because it can now test for a specific timing instead of just
"has a non-zero timing".

Bug: 905412
Change-Id: I91fab300b4005fd7802ce837733665e77766d4b2
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1707870
Auto-Submit: Gabriel Charette <gab@chromium.org>
Commit-Queue: Kentaro Hara <haraken@chromium.org>
Reviewed-by: Kentaro Hara <haraken@chromium.org>
Reviewed-by: kylechar <kylechar@chromium.org>
Reviewed-by: Benoit L <lizeb@chromium.org>
Cr-Commit-Position: refs/heads/master@{#683487}

base/synchronization/waitable_event.h

@@ -96,9 +96,10 @@ class BASE_EXPORT WaitableEvent {
   //   delete e;
   void Wait();
 
-  // Wait up until wait_delta has passed for the event to be signaled.  Returns
-  // true if the event was signaled. Handles spurious wakeups and guarantees
-  // that |wait_delta| will have elapsed if this returns false.
+  // Wait up until wait_delta has passed for the event to be signaled
+  // (real-time; ignores time overrides).  Returns true if the event was
+  // signaled. Handles spurious wakeups and guarantees that |wait_delta| will
+  // have elapsed if this returns false.
   //
   // TimedWait can synchronise its own destruction like |Wait|.
   bool TimedWait(const TimeDelta& wait_delta);

base/synchronization/waitable_event_mac.cc

@@ -19,6 +19,7 @@
 #include "base/threading/scoped_blocking_call.h"
 #include "base/threading/thread_restrictions.h"
 #include "base/time/time.h"
+#include "base/time/time_override.h"
 #include "build/build_config.h"
 
 namespace base {
@@ -140,11 +141,12 @@ bool WaitableEvent::TimedWait(const TimeDelta& wait_delta) {
   }
 
   // TimeTicks takes care of overflow but we special case is_max() nonetheless
-  // to avoid invoking Now() unnecessarily (same for the increment step of the
-  // for loop if the condition variable returns early).
-  // Ref: https://crbug.com/910524#c7
+  // to avoid invoking TimeTicksNowIgnoringOverride() unnecessarily (same for
+  // the increment step of the for loop if the condition variable returns
+  // early). Ref: https://crbug.com/910524#c7
   const TimeTicks end_time =
-      wait_delta.is_max() ? TimeTicks::Max() : TimeTicks::Now() + wait_delta;
+      wait_delta.is_max() ? TimeTicks::Max()
+                          : subtle::TimeTicksNowIgnoringOverride() + wait_delta;
   // Fake |kr| value to boostrap the for loop.
   kern_return_t kr = MACH_RCV_INTERRUPTED;
   for (mach_msg_timeout_t timeout = wait_delta.is_max()
@@ -160,8 +162,8 @@ bool WaitableEvent::TimedWait(const TimeDelta& wait_delta) {
            end_time.is_max()
                ? MACH_MSG_TIMEOUT_NONE
                : std::max<int64_t>(
-                     0,
-                     (end_time - TimeTicks::Now()).InMillisecondsRoundedUp())) {
+                     0, (end_time - subtle::TimeTicksNowIgnoringOverride())
+                            .InMillisecondsRoundedUp())) {
     kr = mach_msg(&msg.header, options, 0, rcv_size, receive_right_->Name(),
                   timeout, MACH_PORT_NULL);
   }

base/synchronization/waitable_event_posix.cc

@@ -17,6 +17,7 @@
 #include "base/threading/scoped_blocking_call.h"
 #include "base/threading/thread_restrictions.h"
 #include "base/time/time.h"
+#include "base/time/time_override.h"
 
 // -----------------------------------------------------------------------------
 // A WaitableEvent on POSIX is implemented as a wait-list. Currently we don't
@@ -196,14 +197,16 @@ bool WaitableEvent::TimedWait(const TimeDelta& wait_delta) {
   // again before unlocking it.
 
   // TimeTicks takes care of overflow but we special case is_max() nonetheless
-  // to avoid invoking Now() unnecessarily (same for the increment step of the
-  // for loop if the condition variable returns early).
-  // Ref: https://crbug.com/910524#c7
+  // to avoid invoking TimeTicksNowIgnoringOverride() unnecessarily (same for
+  // the increment step of the for loop if the condition variable returns
+  // early). Ref: https://crbug.com/910524#c7
   const TimeTicks end_time =
-      wait_delta.is_max() ? TimeTicks::Max() : TimeTicks::Now() + wait_delta;
+      wait_delta.is_max() ? TimeTicks::Max()
+                          : subtle::TimeTicksNowIgnoringOverride() + wait_delta;
   for (TimeDelta remaining = wait_delta; remaining > TimeDelta() && !sw.fired();
-       remaining = end_time.is_max() ? TimeDelta::Max()
-                                     : end_time - TimeTicks::Now()) {
+       remaining = end_time.is_max()
+                       ? TimeDelta::Max()
+                       : end_time - subtle::TimeTicksNowIgnoringOverride()) {
     if (end_time.is_max())
       sw.cv()->Wait();
     else

base/synchronization/waitable_event_win.cc

@@ -17,6 +17,7 @@
 #include "base/threading/scoped_blocking_call.h"
 #include "base/threading/thread_restrictions.h"
 #include "base/time/time.h"
+#include "base/time/time_override.h"
 
 namespace base {
 
@@ -88,13 +89,14 @@ bool WaitableEvent::TimedWait(const TimeDelta& wait_delta) {
   }
 
   // TimeTicks takes care of overflow but we special case is_max() nonetheless
-  // to avoid invoking Now() unnecessarily.
+  // to avoid invoking TimeTicksNowIgnoringOverride() unnecessarily.
   // WaitForSingleObject(handle_.Get(), INFINITE) doesn't spuriously wakeup so
   // we don't need to worry about is_max() for the increment phase of the loop.
   const TimeTicks end_time =
-      wait_delta.is_max() ? TimeTicks::Max() : TimeTicks::Now() + wait_delta;
+      wait_delta.is_max() ? TimeTicks::Max()
+                          : subtle::TimeTicksNowIgnoringOverride() + wait_delta;
   for (TimeDelta remaining = wait_delta; remaining > TimeDelta();
-       remaining = end_time - TimeTicks::Now()) {
+       remaining = end_time - subtle::TimeTicksNowIgnoringOverride()) {
     // Truncate the timeout to milliseconds, rounded up to avoid spinning
     // (either by returning too early or because a < 1ms timeout on Windows
     // tends to return immediately).

base/test/scoped_task_environment.h

@@ -87,27 +87,26 @@ class ScopedTaskEnvironment {
     // Delayed tasks and Time/TimeTicks::Now() use the real-time system clock.
     SYSTEM_TIME,
 
-    // Delayed tasks use a mock clock which only advances (in increments to the
-    // soonest delay) when reaching idle during a FastForward*() call to this
-    // ScopedTaskEnvironment. Or when RunLoop::Run() goes idle on the main
-    // thread with no tasks remaining in the thread pool.
-    // Note: this does not affect threads outside this ScopedTaskEnvironment's
-    // purview (notably: independent base::Thread's).
-    MOCK_TIME,
-
-    // Mock Time/TimeTicks::Now() with the same mock clock used for delayed
-    // tasks. This is useful when a delayed task under test needs to check the
-    // amount of time that has passed since a previous sample of Now() (e.g.
-    // cache expiry).
+    // Delayed tasks use a mock clock which only advances when reaching "idle"
+    // during RunLoop::Run() call on the main thread or a FastForward*() call to
+    // this ScopedTaskEnvironment. "idle" is defined as the main thread and
+    // thread pool being out of ready tasks. When idle, time advances to the
+    // soonest delay -- between main thread and thread pool delayed tasks --
+    // according to the semantics of the current Run*() or FastForward*().
     //
-    // Warning some platform APIs are still real-time, and don't interact with
-    // MOCK_TIME as expected, e.g.:
-    //   PlatformThread::Sleep
-    //   WaitableEvent::TimedWait
-    //   ConditionVariable::TimedWait
+    // This also mocks Time/TimeTicks::Now() with the same mock clock.
     //
-    // TODO(crbug.com/905412): Make MOCK_TIME always mock Time/TimeTicks::Now().
-    MOCK_TIME_AND_NOW,
+    // Warning some platform APIs are still real-time, e.g.:
+    //   * PlatformThread::Sleep
+    //   * WaitableEvent::TimedWait
+    //   * ConditionVariable::TimedWait
+    //   * Delayed tasks on unmanaged base::Thread's and other custom task
+    //     runners.
+    MOCK_TIME,
+
+    // TODO(gab): MOCK_TIME is now equivalent to MOCK_TIME_AND_NOW. Mass migrate
+    // users of MOCK_TIME_AND_NOW to MOCK_TIME.
+    MOCK_TIME_AND_NOW = MOCK_TIME,
 
     // TODO(gab): Consider making MOCK_TIME the default mode.
     DEFAULT = SYSTEM_TIME

base/threading/platform_thread.h

@@ -145,10 +145,11 @@ class BASE_EXPORT PlatformThread {
   // Yield the current thread so another thread can be scheduled.
   static void YieldCurrentThread();
 
-  // Sleeps for the specified duration. Note: The sleep duration may be in
-  // base::Time or base::TimeTicks, depending on platform. If you're looking to
-  // use this in unit tests testing delayed tasks, this will be unreliable -
-  // instead, use base::test::ScopedTaskEnvironment with MOCK_TIME mode.
+  // Sleeps for the specified duration (real-time; ignores time overrides).
+  // Note: The sleep duration may be in base::Time or base::TimeTicks, depending
+  // on platform. If you're looking to use this in unit tests testing delayed
+  // tasks, this will be unreliable - instead, use
+  // base::test::ScopedTaskEnvironment with MOCK_TIME mode.
   static void Sleep(base::TimeDelta duration);
 
   // Sets the thread name visible to debuggers/tools. This will try to

base/threading/platform_thread_win.cc

@@ -16,6 +16,7 @@
 #include "base/threading/scoped_blocking_call.h"
 #include "base/threading/thread_id_name_manager.h"
 #include "base/threading/thread_restrictions.h"
+#include "base/time/time_override.h"
 #include "base/win/scoped_handle.h"
 #include "base/win/windows_version.h"
 #include "build/build_config.h"
@@ -218,9 +219,13 @@ void PlatformThread::YieldCurrentThread() {
 void PlatformThread::Sleep(TimeDelta duration) {
   // When measured with a high resolution clock, Sleep() sometimes returns much
   // too early. We may need to call it repeatedly to get the desired duration.
-  TimeTicks end = TimeTicks::Now() + duration;
-  for (TimeTicks now = TimeTicks::Now(); now < end; now = TimeTicks::Now())
+  // PlatformThread::Sleep doesn't support mock-time, so this always uses
+  // real-time.
+  const TimeTicks end = subtle::TimeTicksNowIgnoringOverride() + duration;
+  for (TimeTicks now = subtle::TimeTicksNowIgnoringOverride(); now < end;
+       now = subtle::TimeTicksNowIgnoringOverride()) {
     ::Sleep(static_cast<DWORD>((end - now).InMillisecondsRoundedUp()));
+  }
 }
 
 // static

base/timer/elapsed_timer.cc

@@ -6,6 +6,10 @@
 
 namespace base {
 
+namespace {
+bool g_mock_elapsed_timers_for_test = false;
+}  // namespace
+
 ElapsedTimer::ElapsedTimer() : begin_(TimeTicks::Now()) {}
 
 ElapsedTimer::ElapsedTimer(ElapsedTimer&& other) : begin_(other.begin_) {}
@@ -15,6 +19,8 @@ void ElapsedTimer::operator=(ElapsedTimer&& other) {
 }
 
 TimeDelta ElapsedTimer::Elapsed() const {
+  if (g_mock_elapsed_timers_for_test)
+    return ScopedMockElapsedTimersForTest::kMockElapsedTime;
   return TimeTicks::Now() - begin_;
 }
 
@@ -23,7 +29,24 @@ ElapsedThreadTimer::ElapsedThreadTimer()
       begin_(is_supported_ ? ThreadTicks::Now() : ThreadTicks()) {}
 
 TimeDelta ElapsedThreadTimer::Elapsed() const {
-  return is_supported_ ? (ThreadTicks::Now() - begin_) : TimeDelta();
+  if (!is_supported_)
+    return TimeDelta();
+  if (g_mock_elapsed_timers_for_test)
+    return ScopedMockElapsedTimersForTest::kMockElapsedTime;
+  return ThreadTicks::Now() - begin_;
+}
+
+// static
+constexpr TimeDelta ScopedMockElapsedTimersForTest::kMockElapsedTime;
+
+ScopedMockElapsedTimersForTest::ScopedMockElapsedTimersForTest() {
+  DCHECK(!g_mock_elapsed_timers_for_test);
+  g_mock_elapsed_timers_for_test = true;
+}
+
+ScopedMockElapsedTimersForTest::~ScopedMockElapsedTimersForTest() {
+  DCHECK(g_mock_elapsed_timers_for_test);
+  g_mock_elapsed_timers_for_test = false;
 }
 
 }  // namespace base

base/timer/elapsed_timer.h

@@ -49,6 +49,25 @@ class BASE_EXPORT ElapsedThreadTimer {
   DISALLOW_COPY_AND_ASSIGN(ElapsedThreadTimer);
 };
 
+// Whenever there's a ScopedMockElapsedTimersForTest in scope,
+// Elapsed(Thread)Timers will always return kMockElapsedTime from Elapsed().
+// This is useful, for example, in unit tests that verify that their impl
+// records timing histograms. It enables such tests to observe reliable timings.
+class BASE_EXPORT ScopedMockElapsedTimersForTest {
+ public:
+  static constexpr TimeDelta kMockElapsedTime =
+      TimeDelta::FromMilliseconds(1337);
+
+  // ScopedMockElapsedTimersForTest is not thread-safe (it must be instantiated
+  // in a test before other threads begin using ElapsedTimers; and it must
+  // conversely outlive any usage of ElapsedTimer in that test).
+  ScopedMockElapsedTimersForTest();
+  ~ScopedMockElapsedTimersForTest();
+
+ private:
+  DISALLOW_COPY_AND_ASSIGN(ScopedMockElapsedTimersForTest);
+};
+
 }  // namespace base
 
 #endif  // BASE_TIMER_ELAPSED_TIMER_H_

base/timer/elapsed_timer_unittest.cc

@@ -27,6 +27,17 @@ TEST(ElapsedTimerTest, Simple) {
   EXPECT_GE(timer.Elapsed(), 2 * kSleepDuration);
 }
 
+TEST(ElapsedTimerTest, Mocked) {
+  ScopedMockElapsedTimersForTest mock_elapsed_timer;
+
+  ElapsedTimer timer;
+  EXPECT_EQ(timer.Elapsed(), ScopedMockElapsedTimersForTest::kMockElapsedTime);
+
+  // Real-time doesn't matter.
+  PlatformThread::Sleep(kSleepDuration);
+  EXPECT_EQ(timer.Elapsed(), ScopedMockElapsedTimersForTest::kMockElapsedTime);
+}
+
 class ElapsedThreadTimerTest : public ::testing::Test {
  protected:
   void SetUp() override {
@@ -73,4 +84,18 @@ TEST_F(ElapsedThreadTimerTest, DoesNotCountSleep) {
   EXPECT_LT(timer.Elapsed(), kSleepDuration);
 }
 
+TEST_F(ElapsedThreadTimerTest, Mocked) {
+  if (!ThreadTicks::IsSupported())
+    return;
+
+  ScopedMockElapsedTimersForTest mock_elapsed_timer;
+
+  ElapsedThreadTimer timer;
+  EXPECT_EQ(timer.Elapsed(), ScopedMockElapsedTimersForTest::kMockElapsedTime);
+
+  // Real-time doesn't matter.
+  PlatformThread::Sleep(kSleepDuration);
+  EXPECT_EQ(timer.Elapsed(), ScopedMockElapsedTimersForTest::kMockElapsedTime);
+}
+
 }  // namespace base

third_party/blink/renderer/platform/bindings/parkable_string_test.cc

@@ -796,6 +796,7 @@ TEST_F(ParkableStringTest, OnlyOneAgingTask) {
 }
 
 TEST_F(ParkableStringTest, ReportTotalUnparkingTime) {
+  base::ScopedMockElapsedTimersForTest mock_elapsed_timers;
   base::HistogramTester histogram_tester;
 
   // On some platforms, initialization takes time, though it happens when
@@ -811,7 +812,8 @@ TEST_F(ParkableStringTest, ReportTotalUnparkingTime) {
   ParkableString parkable(String(data.data(), data.size()).ReleaseImpl());
 
   ParkAndWait(parkable);
-  for (int i = 0; i < 10; ++i) {
+  const int kNumIterations = 10;
+  for (int i = 0; i < kNumIterations; ++i) {
     parkable.ToString();
     ASSERT_FALSE(parkable.Impl()->is_parked());
     WaitForAging();
@@ -822,16 +824,21 @@ TEST_F(ParkableStringTest, ReportTotalUnparkingTime) {
   const size_t compressed_size = parkable.Impl()->compressed_size();
 
   scoped_task_environment_.FastForwardUntilNoTasksRemain();
-  histogram_tester.ExpectTotalCount("Memory.ParkableString.MainThreadTime.5min",
-                                    1);
-  histogram_tester.ExpectBucketCount(
-      "Memory.ParkableString.MainThreadTime.5min", 0, 0);
+
+  // The string is unparked kNumIterations times.
+  histogram_tester.ExpectUniqueSample(
+      "Memory.ParkableString.MainThreadTime.5min",
+      base::ScopedMockElapsedTimersForTest::kMockElapsedTime.InMilliseconds() *
+          kNumIterations,
+      1);
 
   if (base::ThreadTicks::IsSupported()) {
-    histogram_tester.ExpectTotalCount(
-        "Memory.ParkableString.ParkingThreadTime.5min", 1);
-    histogram_tester.ExpectBucketCount(
-        "Memory.ParkableString.ParkingThreadTime.5min", 0, 0);
+    // The string is only compressed once despite the multiple parking/unparking
+    // calls.
+    histogram_tester.ExpectUniqueSample(
+        "Memory.ParkableString.ParkingThreadTime.5min",
+        base::ScopedMockElapsedTimersForTest::kMockElapsedTime.InMilliseconds(),
+        1);
   }
 
   histogram_tester.ExpectUniqueSample("Memory.ParkableString.TotalSizeKb.5min",