diff options
| -rw-r--r-- | base/time.h | 12 | ||||
| -rw-r--r-- | base/time_posix.cc | 2 | ||||
| -rw-r--r-- | base/time_unittest.cc | 39 | ||||
| -rw-r--r-- | base/time_unittest_win.cc | 92 | ||||
| -rw-r--r-- | base/time_win.cc | 152 | ||||
| -rw-r--r-- | base/trace_event.cc | 2 |
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 |