Change to Hi Res timers on Windows.

There are two parts of this:

1) TimeTicks:Now()
Don't call timeBeginPeriod() in all cases.
Use the new SystemMonitor class to watch battery on/off
transitions and use the timeBeginPeriod() only when we're
using the battery.

2) TimeTicks::UnreliableHiResNow()
Change this function from "UnreliableHiResNow()" to 
"HiResNow()".   We still use QPC, but we detect if we're 
on AMD Athlon XP machines which fail on QPC.  For those
systems, we fall back to TimeTicks::Now().

Updated tests to detect hardware specifics of timers.
Output of the test will contain lines such as these:

[ RUN      ] TimeTicks.SubMillisecondTimers
Min timer is: 1us
[       OK ] TimeTicks.SubMillisecondTimers
[ RUN      ] TimeTicks.TimeGetTimeCaps
timeGetTime range is 1 to 1000000ms
[       OK ] TimeTicks.TimeGetTimeCaps
[ RUN      ] TimeTicks.QueryPerformanceFrequency
QueryPerformanceFrequency is 2394.18MHz
[       OK ] TimeTicks.QueryPerformanceFrequency
[ RUN      ] TimeTicks.TimerPerformance
Time::Now: 0.11us per call
TimeTicks::Now: 0.09us per call
TimeTicks::HighResNow: 0.26us per call
[       OK ] TimeTicks.TimerPerformance



Review URL: http://codereview.chromium.org/4092

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@2625 0039d316-1c4b-4281-b951-d872f2087c98

6 files changed, 248 insertions, 51 deletions

diff --git a/base/time.h b/base/time.h
index addb246..4141116 100644
--- a/base/time.h
+++ b/base/time.h
@@ -348,15 +348,15 @@ class TimeTicks {
   }
 
   // Platform-dependent tick count representing "right now."
-  // The resolution of this clock is ~1-5ms.  Resolution varies depending
+  // The resolution of this clock is ~1-15ms.  Resolution varies depending
   // on hardware/operating system configuration.
   static TimeTicks Now();
 
-  // Returns a platform-dependent high-resolution tick count. IT IS BROKEN ON
-  // SOME HARDWARE and is designed to be used for profiling and perf testing
-  // only (see the impl for more information).
-  static TimeTicks UnreliableHighResNow();
-
+  // Returns a platform-dependent high-resolution tick count. Implementation
+  // is hardware dependent and may or may not return sub-millisecond
+  // resolution.  THIS CALL IS GENERALLY MUCH MORE EXPENSIVE THAN Now() AND
+  // SHOULD ONLY BE USED WHEN IT IS REALLY NEEDED.
+  static TimeTicks HighResNow();
 
   // Returns true if this object has not been initialized.
   bool is_null() const {
diff --git a/base/time_posix.cc b/base/time_posix.cc
index 88c49a2..18dc240 100644
--- a/base/time_posix.cc
+++ b/base/time_posix.cc
@@ -137,6 +137,6 @@ TimeTicks TimeTicks::Now() {
 }
 
 // static
-TimeTicks TimeTicks::UnreliableHighResNow() {
+TimeTicks TimeTicks::HighResNow() {
   return Now();
 }
diff --git a/base/time_unittest.cc b/base/time_unittest.cc
index 039913b..db0990f4 100644
--- a/base/time_unittest.cc
+++ b/base/time_unittest.cc
@@ -86,21 +86,38 @@ TEST(Time, LocalMidnight) {
 }
 
 TEST(TimeTicks, Deltas) {
-  TimeTicks ticks_start = TimeTicks::Now();
-  PlatformThread::Sleep(10);
-  TimeTicks ticks_stop = TimeTicks::Now();
-  TimeDelta delta = ticks_stop - ticks_start;
-  EXPECT_GE(delta.InMilliseconds(), 10);
-  EXPECT_GE(delta.InMicroseconds(), 10000);
-  EXPECT_EQ(delta.InSeconds(), 0);
+  for (int index = 0; index < 500; index++) {
+    TimeTicks ticks_start = TimeTicks::Now();
+    PlatformThread::Sleep(10);
+    TimeTicks ticks_stop = TimeTicks::Now();
+    TimeDelta delta = ticks_stop - ticks_start;
+    // Note:  Although we asked for a 10ms sleep, if the
+    // time clock has a finer granularity than the Sleep()
+    // clock, it is quite possible to wakeup early.  Here
+    // is how that works:
+    //      Time(ms timer)      Time(us timer)
+    //          5                   5010
+    //          6                   6010
+    //          7                   7010
+    //          8                   8010
+    //          9                   9000
+    // Elapsed  4ms                 3990us
+    //
+    // Unfortunately, our InMilliseconds() function truncates
+    // rather than rounds.  We should consider fixing this
+    // so that our averages come out better.
+    EXPECT_GE(delta.InMilliseconds(), 9);
+    EXPECT_GE(delta.InMicroseconds(), 9000);
+    EXPECT_EQ(delta.InSeconds(), 0);
+  }
 }
 
-TEST(TimeTicks, UnreliableHighResNow) {
-  TimeTicks ticks_start = TimeTicks::UnreliableHighResNow();
+TEST(TimeTicks, HighResNow) {
+  TimeTicks ticks_start = TimeTicks::HighResNow();
   PlatformThread::Sleep(10);
-  TimeTicks ticks_stop = TimeTicks::UnreliableHighResNow();
+  TimeTicks ticks_stop = TimeTicks::HighResNow();
   TimeDelta delta = ticks_stop - ticks_start;
-  EXPECT_GE(delta.InMilliseconds(), 10);
+  EXPECT_GE(delta.InMicroseconds(), 9000);
 }
 
 TEST(TimeDelta, FromAndIn) {
diff --git a/base/time_unittest_win.cc b/base/time_unittest_win.cc
index 87cf698..4a7120e 100644
--- a/base/time_unittest_win.cc
+++ b/base/time_unittest_win.cc
@@ -3,6 +3,7 @@
 // found in the LICENSE file.
 
 #include <windows.h>
+#include <mmsystem.h>
 #include <process.h>
 
 #include "base/time.h"
@@ -44,7 +45,9 @@ unsigned __stdcall RolloverTestThreadMain(void* param) {
   for (int index = 0; index < counter; index++) {
     TimeTicks now = TimeTicks::Now();
     int64 milliseconds = (now - last).InMilliseconds();
-    EXPECT_GT(milliseconds, 0);
+    // This is a tight loop; we could have looped faster than our
+    // measurements, so the time might be 0 millis.
+    EXPECT_GE(milliseconds, 0);
     EXPECT_LT(milliseconds, 250);
     last = now;
   }
@@ -99,3 +102,90 @@ TEST(TimeTicks, WinRollover) {
     MockTimeTicks::UninstallTicker();
   }
 }
+
+TEST(TimeTicks, SubMillisecondTimers) {
+  // Loop for a bit getting timers quickly.  We want to
+  // see at least one case where we get a new sample in 
+  // less than one millisecond.
+  bool saw_submillisecond_timer = false;
+  int64 min_timer = 1000;
+  TimeTicks last_time = TimeTicks::HighResNow();
+  for (int index = 0; index < 1000; index++) {
+    TimeTicks now = TimeTicks::HighResNow();
+    TimeDelta delta = now - last_time;
+    if (delta.InMicroseconds() > 0 &&
+        delta.InMicroseconds() < 1000) {
+      if (min_timer > delta.InMicroseconds())
+        min_timer = delta.InMicroseconds();
+      saw_submillisecond_timer = true;
+    }
+    last_time = now;
+  }
+  EXPECT_TRUE(saw_submillisecond_timer);
+  printf("Min timer is: %dus\n", min_timer);
+}
+
+TEST(TimeTicks, TimeGetTimeCaps) {
+  // Test some basic assumptions that we expect about how timeGetDevCaps works.
+
+  TIMECAPS caps;
+  MMRESULT status = timeGetDevCaps(&caps, sizeof(caps));
+  EXPECT_EQ(TIMERR_NOERROR, status);
+  if (status != TIMERR_NOERROR) {
+    printf("Could not get timeGetDevCaps\n");
+    return;
+  }
+
+  EXPECT_GE(static_cast<int>(caps.wPeriodMin), 1);
+  EXPECT_GT(static_cast<int>(caps.wPeriodMax), 1);
+  EXPECT_GE(static_cast<int>(caps.wPeriodMin), 1);
+  EXPECT_GT(static_cast<int>(caps.wPeriodMax), 1);
+  printf("timeGetTime range is %d to %dms\n", caps.wPeriodMin,
+    caps.wPeriodMax);
+}
+
+TEST(TimeTicks, QueryPerformanceFrequency) {
+  // Test some basic assumptions that we expect about QPC.
+
+  LARGE_INTEGER frequency;
+  BOOL rv = QueryPerformanceFrequency(&frequency);
+  EXPECT_EQ(TRUE, rv);
+  EXPECT_GT(frequency.QuadPart, 1000000);  // Expect at least 1MHz
+  printf("QueryPerformanceFrequency is %5.2fMHz\n",
+    frequency.QuadPart / 1000000.0);
+}
+
+TEST(TimeTicks, TimerPerformance) {
+  // Verify that various timer mechanisms can always complete quickly.
+  // Note:  This is a somewhat arbitrary test.
+  const int kLoops = 10000;
+  const int kMaxTime = 10;  // Maximum acceptible milliseconds for test.
+
+  typedef TimeTicks (*TestFunc)();
+  struct TestCase {
+    TestFunc func;
+    char *description;
+  };
+  // Cheating a bit here:  assumes sizeof(TimeTicks) == sizeof(Time)
+  // in order to create a single test case list.
+  COMPILE_ASSERT(sizeof(TimeTicks) == sizeof(Time), 
+                 test_only_works_with_same_sizes);
+  TestCase cases[] = { 
+    { reinterpret_cast<TestFunc>(Time::Now), "Time::Now" },
+    { TimeTicks::Now, "TimeTicks::Now" },
+    { TimeTicks::HighResNow, "TimeTicks::HighResNow" },
+    { NULL, "" }
+  };
+
+  int test_case = 0;
+  while (cases[test_case].func) {
+    TimeTicks start = TimeTicks::HighResNow();
+    for (int index = 0; index < kLoops; index++)
+      cases[test_case].func();
+    TimeTicks stop = TimeTicks::HighResNow();
+    EXPECT_LT((stop - start).InMilliseconds(), kMaxTime);
+    printf("%s: %1.2fus per call\n", cases[test_case].description, 
+      (stop - start).InMillisecondsF() * 1000 / kLoops);
+    test_case++;
+  }
+}
diff --git a/base/time_win.cc b/base/time_win.cc
index 32f8333..e7d7ae8 100644
--- a/base/time_win.cc
+++ b/base/time_win.cc
@@ -2,6 +2,38 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+
+// Windows Timer Primer
+//
+// A good article:  http://www.ddj.com/windows/184416651
+// A good mozilla bug:  http://bugzilla.mozilla.org/show_bug.cgi?id=363258
+//
+// The default windows timer, GetSystemTimeAsFileTime is not very precise.
+// It is only good to ~15.5ms.
+//
+// QueryPerformanceCounter is the logical choice for a high-precision timer.
+// However, it is known to be buggy on some hardware.  Specifically, it can
+// sometimes "jump".  On laptops, QPC can also be very expensive to call.
+// It's 3-4x slower than timeGetTime() on desktops, but can be 10x slower
+// on laptops.  A unittest exists which will show the relative cost of various
+// timers on any system.
+//
+// The next logical choice is timeGetTime().  timeGetTime has a precision of
+// 1ms, but only if you call APIs (timeBeginPeriod()) which affect all other
+// applications on the system.  By default, precision is only 15.5ms.
+// Unfortunately, we don't want to call timeBeginPeriod because we don't
+// want to affect other applications.  Further, on mobile platforms, use of
+// faster multimedia timers can hurt battery life.  See the intel 
+// article about this here: 
+// http://softwarecommunity.intel.com/articles/eng/1086.htm
+//
+// To work around all this, we're going to generally use timeGetTime().  We
+// will only increase the system-wide timer if we're not running on battery
+// power.  Using timeBeginPeriod(1) is a requirement in order to make our
+// message loop waits have the same resolution that our time measurements
+// do.  Otherwise, WaitForSingleObject(..., 1) will no less than 15ms when
+// there is nothing else to waken the Wait.
+
 #include "base/time.h"
 
 #pragma comment(lib, "winmm.lib")
@@ -11,7 +43,9 @@
 #include "base/basictypes.h"
 #include "base/lock.h"
 #include "base/logging.h"
+#include "base/cpu.h"
 #include "base/singleton.h"
+#include "base/system_monitor.h"
 
 namespace {
 
@@ -174,6 +208,7 @@ DWORD timeGetTimeWrapper() {
   return timeGetTime();
 }
 
+
 DWORD (*tick_function)(void) = &timeGetTimeWrapper;
 
 // We use timeGetTime() to implement TimeTicks::Now().  This can be problematic
@@ -181,20 +216,20 @@ DWORD (*tick_function)(void) = &timeGetTimeWrapper;
 // which will roll over the 32-bit value every ~49 days.  We try to track
 // rollover ourselves, which works if TimeTicks::Now() is called at least every
 // 49 days.
-class NowSingleton {
+class NowSingleton : public base::SystemMonitor::PowerObserver {
  public:
   NowSingleton()
-      : rollover_(TimeDelta::FromMilliseconds(0)), last_seen_(0) {
-    // Request a resolution of 1ms from timeGetTime().  This can have some
-    // consequences on other applications (see MSDN), but we've found that it
-    // is very common in other applications (Flash, Media Player, etc), so it
-    // is not really a dangerous thing to do.  We need this because the default
-    // resolution of ~15ms is much too low for accurate timing and timers.
-    ::timeBeginPeriod(1);
+    : rollover_(TimeDelta::FromMilliseconds(0)),
+      last_seen_(0), 
+      hi_res_clock_enabled_(false) {
+    base::SystemMonitor* system = base::SystemMonitor::Get();
+    system->AddObserver(this);
+    UseHiResClock(!system->BatteryPower());
   }
 
   ~NowSingleton() {
-    ::timeEndPeriod(1);
+    UseHiResClock(false);
+    base::SystemMonitor::Get()->RemoveObserver(this);
   }
 
   TimeDelta Now() {
@@ -208,10 +243,30 @@ class NowSingleton {
     return TimeDelta::FromMilliseconds(now) + rollover_;
   }
 
+  // Interfaces for monitoring Power changes.
+  void OnPowerStateChange(base::SystemMonitor* system) {
+    UseHiResClock(!system->BatteryPower());
+  }
+
+  void OnSuspend(base::SystemMonitor* system) {}
+  void OnResume(base::SystemMonitor* system) {}
+
  private:
+  // Enable or disable the faster multimedia timer.
+  void UseHiResClock(bool enabled) {
+    if (enabled == hi_res_clock_enabled_)
+      return;
+    if (enabled)
+      timeBeginPeriod(1);
+    else
+      timeEndPeriod(1);
+    hi_res_clock_enabled_ = enabled;
+  }
+
   Lock lock_;  // To protected last_seen_ and rollover_.
   TimeDelta rollover_;  // Accumulation of time lost due to rollover.
   DWORD last_seen_;  // The last timeGetTime value we saw, to detect rollover.
+  bool hi_res_clock_enabled_;
 
   DISALLOW_COPY_AND_ASSIGN(NowSingleton);
 };
@@ -244,32 +299,75 @@ class NowSingleton {
 // (3) System time. The system time provides a low-resolution (typically 10ms
 // to 55 milliseconds) time stamp but is comparatively less expensive to
 // retrieve and more reliable.
-class UnreliableHighResNowSingleton {
+class HighResNowSingleton {
  public:
-  UnreliableHighResNowSingleton() : ticks_per_microsecond_(0) {
+  HighResNowSingleton() 
+    : ticks_per_microsecond_(0.0),
+      skew_(0) {  
+    InitializeClock();
+
+    // On Athlon X2 CPUs (e.g. model 15) QueryPerformanceCounter is
+    // unreliable.  Fallback to low-res clock.
+    base::CPU cpu;
+    if (cpu.vendor_name() == "AuthenticAMD" && cpu.family() == 15)
+      DisableHighResClock();
+  }
+
+  bool IsUsingHighResClock() {
+    return ticks_per_microsecond_ != 0.0;
+  }
+
+  void DisableHighResClock() {
+    ticks_per_microsecond_ = 0.0;
+  }
+
+  TimeDelta Now() {
+    // Our maximum tolerance for QPC drifting.
+    const int kMaxTimeDrift = 50 * Time::kMicrosecondsPerMillisecond;
+
+    if (IsUsingHighResClock()) {
+      int64 now = UnreliableNow();
+
+      // Verify that QPC does not seem to drift.
+      DCHECK(now - ReliableNow() - skew_ < kMaxTimeDrift);
+
+      return TimeDelta::FromMicroseconds(now);
+    }
+
+    // Just fallback to the slower clock.
+    return Singleton<NowSingleton>::get()->Now();
+  }
+
+ private:
+  // Synchronize the QPC clock with GetSystemTimeAsFileTime.
+  void InitializeClock() {
     LARGE_INTEGER ticks_per_sec = {0};
     if (!QueryPerformanceFrequency(&ticks_per_sec))
       return;  // Broken, we don't guarantee this function works.
-    ticks_per_microsecond_ =
-        ticks_per_sec.QuadPart / Time::kMicrosecondsPerSecond;
-  }
+    ticks_per_microsecond_ = static_cast<float>(ticks_per_sec.QuadPart) /
+      static_cast<float>(Time::kMicrosecondsPerSecond);
 
-  bool IsBroken() {
-    return ticks_per_microsecond_ == 0;
+    skew_ = UnreliableNow() - ReliableNow();
   }
 
-  TimeDelta Now() {
+  // Get the number of microseconds since boot in a reliable fashion
+  int64 UnreliableNow() {
     LARGE_INTEGER now;
     QueryPerformanceCounter(&now);
-    return TimeDelta::FromMicroseconds(now.QuadPart / ticks_per_microsecond_);
+    return static_cast<int64>(now.QuadPart / ticks_per_microsecond_);
+  }
+
+  // Get the number of microseconds since boot in a reliable fashion
+  int64 ReliableNow() {
+    return Singleton<NowSingleton>::get()->Now().InMicroseconds();
   }
 
- private:
   // Cached clock frequency -> microseconds. This assumes that the clock
   // frequency is faster than one microsecond (which is 1MHz, should be OK).
-  int64 ticks_per_microsecond_;  // 0 indicates QPF failed and we're broken.
+  float ticks_per_microsecond_;  // 0 indicates QPF failed and we're broken.
+  int64 skew_;  // Skew between lo-res and hi-res clocks (for debugging).
 
-  DISALLOW_COPY_AND_ASSIGN(UnreliableHighResNowSingleton);
+  DISALLOW_COPY_AND_ASSIGN(HighResNowSingleton);
 };
 
 }  // namespace
@@ -288,14 +386,6 @@ TimeTicks TimeTicks::Now() {
 }
 
 // static
-TimeTicks TimeTicks::UnreliableHighResNow() {
-  UnreliableHighResNowSingleton* now =
-      Singleton<UnreliableHighResNowSingleton>::get();
-
-  if (now->IsBroken()) {
-    NOTREACHED() << "QueryPerformanceCounter is broken.";
-    return TimeTicks(0);
-  }
-
-  return TimeTicks() + now->Now();
+TimeTicks TimeTicks::HighResNow() {
+  return TimeTicks() + Singleton<HighResNowSingleton>::get()->Now();
 }
diff --git a/base/trace_event.cc b/base/trace_event.cc
index 4ed41d5..92939d5 100644
--- a/base/trace_event.cc
+++ b/base/trace_event.cc
@@ -136,7 +136,7 @@ void TraceLog::Trace(const std::string& name,
     return;
 
 #ifdef USE_UNRELIABLE_NOW
-  TimeTicks tick = TimeTicks::UnreliableHighResNow();
+  TimeTicks tick = TimeTicks::HighResNow();
 #else
   TimeTicks tick = TimeTicks::Now();
 #endif