High resolution time on Windows

[James Simonsen]

In the past, we've avoided using TimeTicks::HighResNow() for anything but benchmarking. On Windows, HighResNow() is implemented using QueryPerformanceCounter, which the comments say is expensive and buggy on some machines.

The W3C HighResTime [1] spec requires us to report sub-millisecond resolution to JavaScript. Right now, we don't, because we're afraid to use HighResNow(). Users are already complaining about this [2]. Meanwhile, IE and FF both report sub-millisecond times successfully.

Are we still opposed to using HighResNow()?

We already have some logic that tries to determine if QPC is broken and falls back to normal millisecond resolution. Is there anything more we can do to beef that up? Or is there anything else we can use in Windows to get reliable sub-millisecond times?

Thanks,

James

[1] http://www.w3.org/TR/2012/REC-hr-time-20121217/

[2] https://code.google.com/p/chromium/issues/detail?id=158234

[Darin Fisher]

How does Mozilla implement window.performance.now()?  I don't know of any method other than QPC to get sub-millisecond resolution on Windows.  It was my understanding that it is considerably more expensive to call than timeGetTime().  I don't know how much this matters for the intended use case of performance.now().  Why is sub-millisecond resolution for window.performance.now() important?

-Darin

--
Chromium Developers mailing list: chromi...@chromium.org
View archives, change email options, or unsubscribe:
http://groups.google.com/a/chromium.org/group/chromium-dev

[Christian Biesinger]

Yes, Mozilla uses QPC for window.performance.now():
http://mxr.mozilla.org/mozilla-central/source/dom/base/nsPerformance.cpp#225
http://mxr.mozilla.org/mozilla-central/source/xpcom/ds/TimeStamp_windows.cpp#7
http://mxr.mozilla.org/mozilla-central/source/xpcom/ds/TimeStamp_windows.cpp#610
http://mxr.mozilla.org/mozilla-central/source/xpcom/ds/TimeStamp_windows.cpp#753

Looks like for certain systems it does some adjustments based on the
QPC results using GetTickCount64... and there's also some logic to
use GTC only if QPC is observed to be unreliable.

-christian

[James Simonsen]

They use QPC with a fallback to GetTickCount(), which is similar to us, except that we fallback to timeGetTime(). They have different heuristics to decide if QPC is safe. I'm not sure which are better.

From offline conversations, it seems that users are trying to time code within a single 60Hz frame. Milliseconds aren't sufficient for that.

James

On Tue, Jan 8, 2013 at 3:23 PM, Darin Fisher <da...@chromium.org> wrote:

[John Bauman]

How expensive is timeGetTime? Last I checked, QPC was around 500 cycles at worst, and on modern computers it turns into an RDTSC instruction, which is pretty cheap.

On Tue, Jan 8, 2013 at 3:23 PM, Darin Fisher <da...@chromium.org> wrote:

[James Simonsen]

According to the comments in base/time_win.cc [1], timeGetTime is 3-10x faster than QPC.

James

[1] https://code.google.com/searchframe#OAMlx_jo-ck/src/base/time_win.cc&exact_package=chromium&q=time_win.cc&type=cs&l=16

[Tom Wiltzius]

On Tue, Jan 8, 2013 at 3:33 PM, James Simonsen <simo...@chromium.org> wrote:

They use QPC with a fallback to GetTickCount(), which is similar to us, except that we fallback to timeGetTime(). They have different heuristics to decide if QPC is safe. I'm not sure which are better.

From offline conversations, it seems that users are trying to time code within a single 60Hz frame. Milliseconds aren't sufficient for that.

e.g. for comparisons with the now-theoretically-high-resolution timestamp for requestAnimationFrame

[Darin Fisher]

My understanding is that timeGetTime() is quite cheap.  It is just three integer reads plus a validation that the integers are in monotonically increasing order.  If that checks out, then the time value is the second integer read, else the steps are repeated.  The kernel periodically updates these numbers at the frequency specified by timeBeginPeriod.

I don't know much about the cost of GetTickCount.

Some more discussion and details here:

http://stackoverflow.com/questions/6764991/performance-impact-of-queryperformancecounter

It certainly seems like QPC could potentially be too costly.

-Darin

On Tue, Jan 8, 2013 at 3:35 PM, John Bauman <jba...@chromium.org> wrote:

[Darin Fisher]

This Dr. Dobb's article, although a bit old, has some performance results:

http://www.drdobbs.com/windows/win32-performance-measurement-options/184416651?pgno=4

-Darin

[Sigurður Ásgeirsson]

I remember looking into this recently, and I think it's less and less true that QPC is expensive. On all "recent" x86/x64 CPUs, the cycle counter (RDTSC) has been fixed to make a reliable, low-cost, low-power, high-resolution, accurate wall-clock timer (see [http://en.wikipedia.org/wiki/Time_Stamp_Counter#Implementation_in_various_processors]). On CPUs where this is true, running recent systems (probably Vista or "better"), QPC is a bit of function preamble, followed by an RDTSC instruction in user mode.

On Windows XP QPC is still a system call, but the system call then subsequently calls RDTSC where available.

IMHO the fact that XP still goes to kernel for QPC argues for writing our own implementation that uses RTDSC directly where safe (perhaps as declared by CPUID), falling back to QPC or timeGetTime or such...

Witness disassembly on my Win7 system:

0:000> uf kernel32!queryperformancecounter

kernel32!QueryPerformanceCounter:

76c31732 ff25d40dc376    jmp     dword ptr [kernel32!_imp__QueryPerformanceCounter (76c30dd4)]

ntdll!RtlQueryPerformanceCounter:

777d88a4 8bff            mov     edi,edi

777d88a6 55              push    ebp

777d88a7 8bec            mov     ebp,esp

777d88a9 51              push    ecx

777d88aa 51              push    ecx

777d88ab f605ed02fe7f01  test    byte ptr [SharedUserData+0x2ed (7ffe02ed)],1

777d88b2 0f844bf50400    je      ntdll!RtlQueryPerformanceCounter+0x55 (77827e03)

ntdll!RtlQueryPerformanceCounter+0x10:

777d88b8 56              push    esi

ntdll!RtlQueryPerformanceCounter+0x11:

777d88b9 8b0db803fe7f    mov     ecx,dword ptr [SharedUserData+0x3b8 (7ffe03b8)]

777d88bf 8b35bc03fe7f    mov     esi,dword ptr [SharedUserData+0x3bc (7ffe03bc)]

777d88c5 a1b803fe7f      mov     eax,dword ptr [SharedUserData+0x3b8 (7ffe03b8)]

777d88ca 8b15bc03fe7f    mov     edx,dword ptr [SharedUserData+0x3bc (7ffe03bc)]

777d88d0 3bc8            cmp     ecx,eax

777d88d2 75e5            jne     ntdll!RtlQueryPerformanceCounter+0x11 (777d88b9)

ntdll!RtlQueryPerformanceCounter+0x2c:

777d88d4 3bf2            cmp     esi,edx

777d88d6 75e1            jne     ntdll!RtlQueryPerformanceCounter+0x11 (777d88b9)

ntdll!RtlQueryPerformanceCounter+0x30:

777d88d8 0f31            rdtsc

[snip]

On an XP SP2 system this is still a system call:

0:000> uf kernel32!QueryPerformanceCounter

kernel32!QueryPerformanceCounter:

7c80a4c7 8bff            mov     edi,edi

7c80a4c9 55              push    ebp

7c80a4ca 8bec            mov     ebp,esp

7c80a4cc 51              push    ecx

7c80a4cd 51              push    ecx

7c80a4ce 8d45f8          lea     eax,[ebp-8]

7c80a4d1 50              push    eax

7c80a4d2 ff7508          push    dword ptr [ebp+8]

7c80a4d5 ff15dc13807c    call    dword ptr [kernel32!_imp__NtQueryPerformanceCounter (7c8013dc)]

7c80a4db 85c0            test    eax,eax

7c80a4dd 0f8c17760300    jl      kernel32!QueryPerformanceCounter+0x18 (7c841afa)

[snip]

But the system call subsequently uses RDTSC where available - in kernel this bottlenecks in hal!KeQueryPerformanceCounter:

lkd> uf hal!KeQueryPerformanceCounter

hal!HalpAcpiTimerQueryPerfCount:

806e5c78 a0dce06e80      mov     al,byte ptr [hal!HalpUse8254 (806ee0dc)]

806e5c7d 0ac0            or      al,al

806e5c7f 752d            jne     hal!HalpAcpiTimerQueryPerfCount+0x36 (806e5cae)

hal!HalpAcpiTimerQueryPerfCount+0x9:

806e5c81 8b4c2404        mov     ecx,dword ptr [esp+4]

806e5c85 0bc9            or      ecx,ecx

806e5c87 7412            je      hal!HalpAcpiTimerQueryPerfCount+0x23 (806e5c9b)

hal!HalpAcpiTimerQueryPerfCount+0x11:

806e5c89 64a1a4000000    mov     eax,dword ptr fs:[000000A4h]

806e5c8f 648b15a8000000  mov     edx,dword ptr fs:[0A8h]

806e5c96 8901            mov     dword ptr [ecx],eax

806e5c98 895104          mov     dword ptr [ecx+4],edx

hal!HalpAcpiTimerQueryPerfCount+0x23:

806e5c9b 0f31            rdtsc

806e5c9d 640305ac000000  add     eax,dword ptr fs:[0ACh]

806e5ca4 641315b0000000  adc     edx,dword ptr fs:[0B0h]

806e5cab c20400          ret     4

[snip fallback]

Siggi

[Juan Lang]

2013/1/10 Sigurður Ásgeirsson <si...@chromium.org>:

> I remember looking into this recently, and I think it's less and less true
> that QPC is expensive. On all "recent" x86/x64 CPUs, the cycle counter
> (RDTSC) has been fixed to make a reliable, low-cost, low-power,
> high-resolution, accurate wall-clock timer (see
> [http://en.wikipedia.org/wiki/Time_Stamp_Counter#Implementation_in_various_processors]).
> On CPUs where this is true, running recent systems (probably Vista or
> "better"), QPC is a bit of function preamble, followed by an RDTSC
> instruction in user mode.
> On Windows XP QPC is still a system call, but the system call then
> subsequently calls RDTSC where available.
>
> IMHO the fact that XP still goes to kernel for QPC argues for writing our
> own implementation that uses RTDSC directly where safe (perhaps as declared
> by CPUID), falling back to QPC or timeGetTime or such...
>
> Witness disassembly on my Win7 system:

Off-topic, but please don't post disassembly of a closed-source binary
on an open-source mailing list. You may discuss what you learned
without issue, but those of us who contribute to open source projects
where there is a plausible threat of lawsuit would really prefer not
to have seen source or disassembly of any related closed source
product.

Thanks,
--Juan

[Scott Graham]

(Reviving this somewhat old thread because I was looking into timing for other reasons and got results that I found surprising.)

I modified base/time_win_unittest.cc, TimeTicks.TimerPerformance to:

- increase the number of loop iterations

- add cases for calling functions that we don't call via base/time.h

- add tests for calling windows api functions directly

ref: https://codereview.chromium.org/12045074

[trunk]D:\src\cr\src>out\Release\base_unittests --gtest_filter=TimeTicks.TimerPerformance

...

Time::Now: 0.05us per call

GetTickCount64: 0.01us per call

__rdtsc: 0.01us per call

timeGetTime: 0.02us per call

QueryPerformanceCounter: 0.01us per call

TimeTicks::Now: 0.05us per call

TimeTicks::HighResNow: 0.04us per call

...

(TimeTicks::Now ~= timeGetTime, and TimeTicks::HighResNow ~= QueryPerformanceCounter)

Surprising findings:

1. TimeTicks::Now is actually slower than TimeTicks::HighResNow

2. The overhead of our wrappers and corrections dwarfs the actual function

The usual caveats of "only my machine" (Xeon / Win8), "benchmarks suck", etc. apply of course.

http://randomascii.wordpress.com/2011/07/29/rdtsc-in-the-age-of-sandybridge/ is interesting too, and I reproduced the results described there. On "many" recent processors (see Siggi's link: <http://en.wikipedia.org/wiki/Time_Stamp_Counter#Implementation_in_various_processors>), __rdtsc isn't affected by scaling gunk and produces a uniform, high resolution counter.

I guess this doesn't tell us much, other than it's probably worth designing a field experiment to measure availability, reliability, and frequency of the available timing mechanisms on our user's machines (and associate that with the processor family and model).

[Sigurður Ásgeirsson]

Hey Scott,

if you go chase this, I think you'll find that on Windows XP, QPC is always a system call, and so will be quite costly. This is true even when RTDSC is ultimately used as timer, as on XP there doesn't seem to be a user-mode bypass for this situation.

The best of all worlds is probably to implement the user-mode bypass to RTDSC for the high-resolution timer in base, based on the results of a CPUID test or some such.

Siggi

[Darin Fisher]

Very interesting!  Thanks for poking at this.  I agree, we should probably follow this up with some kind of field experiment.  (We have some WinXP machines in the office too.)

-Darin

[James Simonsen]

On Mon, Jan 28, 2013 at 7:02 AM, Darin Fisher <da...@chromium.org> wrote:

Very interesting!  Thanks for poking at this.  I agree, we should probably follow this up with some kind of field experiment.  (We have some WinXP machines in the office too.)

Googlers can see the initial results of the field experiment on Canary channel here:

https://uma.googleplex.com/histograms?dayCount=1&endDate=06-11-2013&version=29.0.1535.2-W&group=WinTimeTicks

Most users seem to be an order of magnitude slower than Scott's machine. Most users' QPC calls take 0.4us and the slowest outlier is 4us. In the field experiment, the QPC call is in a loop with a couple of other statements, so that could explain why it's not quite as quick as the benchmark.

I was surprised there's no obvious bimodal distribution. I was expecting to see one based on whether QPC is a syscall, but it's not clearly there.

Based on these early results, I'm interested in switching Time::Now() to use QPC at least on Canary channel for users with non-stop TSC processors. Thoughts?

The plan would be to expand it as we get more confirmation from other channels. We should also consider other ways of identifying reliable QPC implementations, besides non-stop TSC.

James

[Darin Fisher]

This looks very promising!

Would you consider an experiment where you measure the overhead of timeGetTime?  Or, maybe you already know the answer to this question.  How does the overhead of timeGetTime compare to the overhead of QPC?

-Darin

[James Simonsen]

On Wed, Jun 12, 2013 at 11:14 AM, Darin Fisher <da...@chromium.org> wrote:

This looks very promising!

Would you consider an experiment where you measure the overhead of timeGetTime?  Or, maybe you already know the answer to this question.  How does the overhead of timeGetTime compare to the overhead of QPC?

I'd assumed it'd be similar to Scott's benchmark results from earlier, but I will also add it to experiment to see it from other users.

James

[Darin Fisher]

OK, I see.  So, it seems like we can probably proceed w/ QPC and just monitor these histograms.  Things might look different on the stable channel, where the distribution of machines and software varies more.

[Alpha Lam]

Reviving this old thread.

The histograms shows that 68% of M35 supports RDTSC. And we already have code to fallback. Shall we turn on HighResNow by default in Windows?

Alpha

--

[Darin Fisher]

+trung, who just had to disable HighResNow usage in Mojo to workaround some issues. maybe he has some thoughts on this thread.

[Viet-Trung Luu]

Let me quote our Windows PlatformThread::Sleep() implementation:

// static
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;
  TimeTicks now;
  while ((now = TimeTicks::Now()) < end)
    ::Sleep((end - now).InMillisecondsRoundedUp());
}

This implementation is actually a relatively recent change, namely crrev.com/222396, which made Now be HighResNow (and which since been undone, I believe).

There may be two issues:

a) Now() (timeGetTime()) and HighResNow() (QPC) appear to be significantly inconsistent, some of the time. This may only be a problem on loaded VMs (like on bots), but still.... (Admittedly, I haven't analyzed this super-carefully. Experimenting and collecting data for things that only occur under such conditions is a bit annoying to do.)

b) What are the guarantees of system APIs like Sleep, WaitForSingleObject (which takes a timeout), etc.?

The naive hope would be that, e.g., Sleep(duration) always sleeps for at least the specified duration, as measured by say both timeGetTime() and QPC (and hopefully also rdtsc). Our PlatformThread::Sleep() implementation (which was apparently made complicated only due to switching Now to HighResNow causing test failures on bots) indicates that this is not the case.

Another possibility is that it sleeps for the specified duration as measured by timeGetTime(). In that case, it may sleep for much less than the requested duration, even when things are operating normally.[1] E.g., if the timeGetTime resolution is 10 ms, and you sleep for 10 ms, then Sleep() may sleep for very little time, if the timeGetTime timer increments shortly after the sleep begins.

In that case, with "Now = timeGetTime", everything remains consistent. But switching Now to QPC may be somewhat dangerous (of course, there's not only Sleep to consider, but every other system API that involves timeouts, etc.).

[1] I suspect that the problem I'm seeing in a) is not normal operation. My hunch would be that in the VM QPC is hooked up to "real time" while the ticks for timeGetTime may sometimes occur less often than they're supposed to be occurring, which might lead to sleep durations as measured by HighResNow()/QPC being much longer than durations measured by Now()/timeGetTime().

[Sigurður Ásgeirsson]

On Tue, Jun 24, 2014 at 12:21 PM, Viet-Trung Luu <viettr...@chromium.org> wrote:

Let me quote our Windows PlatformThread::Sleep() implementation:

// static
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;
  TimeTicks now;
  while ((now = TimeTicks::Now()) < end)
    ::Sleep((end - now).InMillisecondsRoundedUp());
}

This implementation is actually a relatively recent change, namely crrev.com/222396, which made Now be HighResNow (and which since been undone, I believe).

There may be two issues:

a) Now() (timeGetTime()) and HighResNow() (QPC) appear to be significantly inconsistent, some of the time. This may only be a problem on loaded VMs (like on bots), but still.... (Admittedly, I haven't analyzed this super-carefully. Experimenting and collecting data for things that only occur under such conditions is a bit annoying to do.)

b) What are the guarantees of system APIs like Sleep, WaitForSingleObject (which takes a timeout), etc.?

The naive hope would be that, e.g., Sleep(duration) always sleeps for at least the specified duration, as measured by say both timeGetTime() and QPC (and hopefully also rdtsc). Our PlatformThread::Sleep() implementation (which was apparently made complicated only due to switching Now to HighResNow causing test failures on bots) indicates that this is not the case.

Sleep is explicitly documented to under-sleep in MSDN [http://msdn.microsoft.com/en-ca/library/windows/desktop/ms686298(v=vs.85).aspx]:

" If dwMilliseconds is less than the resolution of the system clock, the thread may sleep for less than the specified length of time. If dwMilliseconds is greater than one tick but less than two, the wait can be anywhere between one and two ticks, and so on."

The next sentence talks about how to determine and achieve the best possible time resolution for Sleep. Note that this may be expensive in practice, as from what I understand, the hardware interrupt tick frequency is bumped to support higher sleep time resolution.

[Viet-Trung Luu]

On Tue, Jun 24, 2014 at 10:32 AM, Sigurður Ásgeirsson <si...@chromium.org> wrote:

On Tue, Jun 24, 2014 at 12:21 PM, Viet-Trung Luu <viettr...@chromium.org> wrote:

Let me quote our Windows PlatformThread::Sleep() implementation:

// static
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;
  TimeTicks now;
  while ((now = TimeTicks::Now()) < end)
    ::Sleep((end - now).InMillisecondsRoundedUp());
}

This implementation is actually a relatively recent change, namely crrev.com/222396, which made Now be HighResNow (and which since been undone, I believe).

There may be two issues:

a) Now() (timeGetTime()) and HighResNow() (QPC) appear to be significantly inconsistent, some of the time. This may only be a problem on loaded VMs (like on bots), but still.... (Admittedly, I haven't analyzed this super-carefully. Experimenting and collecting data for things that only occur under such conditions is a bit annoying to do.)

b) What are the guarantees of system APIs like Sleep, WaitForSingleObject (which takes a timeout), etc.?

The naive hope would be that, e.g., Sleep(duration) always sleeps for at least the specified duration, as measured by say both timeGetTime() and QPC (and hopefully also rdtsc). Our PlatformThread::Sleep() implementation (which was apparently made complicated only due to switching Now to HighResNow causing test failures on bots) indicates that this is not the case.

Sleep is explicitly documented to under-sleep in MSDN [http://msdn.microsoft.com/en-ca/library/windows/desktop/ms686298(v=vs.85).aspx]:

" If dwMilliseconds is less than the resolution of the system clock, the thread may sleep for less than the specified length of time. If dwMilliseconds is greater than one tick but less than two, the wait can be anywhere between one and two ticks, and so on."

This behavior is consistent with the hypothesis that the amount of time slept is always at least the requested amount, if you measure using timeGetTime(). (A minor change in implementation could have made it err on the other side.)

I'd also guess that on a (system clock) timer tick, the kernel simply increments the value returned by timeGetTime() by what it thinks the period of the timer is (rather than update it using a "true" timer -- this is entirely natural, especially if a cheap, reliable clock isn't available). This would be consistent with what I apparently observed on loaded bots (running VMs) -- a Sleep duration, as measured by QPC/HighResNow far exceeding the requested duration. If a machine is oversubscribed in terms of VMs, being loaded could mean ticks being delayed/missed (which would mean that timeGetTime lags, whereas rdtsc is still "reliable").

If it really is the case that timeGetTime() time is scheduler time (and that its value isn't updated from the same source as QPC, if less often), then one would expect all the system APIs with timeouts to be consistent with timeGetTime(), but not necessarily QPC. (Even ignoring loaded, oversubscribed VMs, timeGetTime() and QPC would then probably be at least slightly inconsistent, in either direction.)

[Paweł Hajdan, Jr.]

FYI there is a test flakiness bug that might be QPC or other time change related: https://code.google.com/p/chromium/issues/detail?id=396384

Please take a look and see if it could be caused by some changes made to how time works on Windows.

Paweł