902216 - On windows, performance.now() isn't more precise than Date.now()

Status: RESOLVED INVALID

(Core :: DOM: Core & HTML, defect)

Description

[Martin Bouladour]

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:22.0) Gecko/20100101 Firefox/22.0 (Beta/Release)
Build ID: 20130624104217

Steps to reproduce:

On Firefox 23 Windows, I called performance.now().


Actual results:

It returned an integer (ms).


Expected results:

It should have returned a decimal precise to at least 1/1000th of a millisecond. As does Firefox Linux, and as the MDN document says https://developer.mozilla.org/en-US/docs/Web/API/window.performance.now

Comment 1

[Jeff Walden [:Waldo]]

performance.now() is a DOM API, ergo the bug should reside there, at first.  (Might be it should move to XPCOM, as the implementation of the underlying function is there.  But...)

On the Win7 box I have available, performance.now() does indeed (in the latest WOW64 nightly) return fractional times.  Does anyone else see the behavior reported here?

Comment 2

[Masatoshi Kimura [:emk]]

Works for me, too.
User Agent: Mozilla/5.0 (Windows NT 5.1; rv:23.0) Gecko/20100101 Firefox/23.0

Comment 3

[Boris Zbarsky [:bzbarsky]]

Reporter, what Windows version were you testing on?

Comment 4

[Martin Bouladour]

Reporter here.

The version of Windows I tested on was: Windows 7 Ultimate edition SP1 64 bit. The version of Firefox is 23 without any add-ons installed. The page I tested on didn't change the browser's window API whatsoever.

I tried to reproduce the bug and I found that it is not always reproductible. Actually most of the time performance.now() behaves as it should. I'm doing some more testing and hopefully I'll provide a test case that reproduces the bug.

Comment 5

[Martin Bouladour]

After some testing, I only found this bug on Firefox Windows 7 inside a virtual machine (VirtualBox). On another computer where Windows 7 is installed directly, I was not able to reproduce the bug. Maybe I should have said before that it was an instance of Windows inside a virtual machine (sorry).

As far as I understood, the problem is: under Windows 7 inside VirtualBox under Fedora Linux, Firefox's performance.now behaves nicely for some time, and then after a while it starts to behaves like Date.now. Especially when multiple tabs use performance.now.

This is annoying for performance testing using a virtual machine. But I reckon this is not as bad as this bug report's title indicates.

Does someone know if there are edge cases in Firefox where performance.now falls back to Date.now?

Comment 6

[Martin Bouladour]

Response to my own question: yes, Firefox falls back to less-precise timer when the more-precise one seems not reliable.

Browsing the source code of Firefox, I found TimeDelta Now() in http://mxr.mozilla.org/mozilla-central/source/ipc/chromium/src/base/time_win.cc#308

308   TimeDelta Now() {
309     // Our maximum tolerance for QPC drifting.
310     const int kMaxTimeDrift = 50 * Time::kMicrosecondsPerMillisecond;
311 
312     if (IsUsingHighResClock()) {
313       int64_t now = UnreliableNow();
314 
315       // Verify that QPC does not seem to drift.
316       DCHECK(now - ReliableNow() - skew_ < kMaxTimeDrift);
317 
318       return TimeDelta::FromMicroseconds(now);
319     }
320 
321     // Just fallback to the slower clock.
322     return Singleton<NowSingleton>::get()->Now();
323   

I believe that under Windows 7 inside VirtualBox, the "maximum tolerance for QPC drifting" is reached after some time and then Firefox just falls back to the regular, less-precise clock.

QPC stands for Query Performance Counter, an API to the High Precision Event Timer (a PC hardware timer). I think it gets skewed by VirtualBox's hardware emulation in some way. And thus Firefox ditches it as unreliable.

This is not a bug of Firefox after all. Sorry for wasting your time.

Comment 7

[Martin Bouladour]

FYI, under Windows 7 inside VirtualBox, the behavior of Chrome's performance.now is pretty much the same as Firefox's (i.e. does't work), but for some reasons Internet Explorer 10's works fine. Either IE10 uses another high-res timer that is not skewed by the hardware emulation, or it doesn't check for drifting. Go figure...

Comment 8

[Boris Zbarsky [:bzbarsky]]

Fwiw, the code quoted in comment 6 has nothing to do with performance.now().

The code used by performance.now() is http://mxr.mozilla.org/mozilla-central/source/xpcom/ds/TimeStamp_windows.cpp which does similar checks for QPC being insane: see TimeStampValue::CheckQPC and the compares to kMaxFailuresPerInterval and resulting disabling of attempts to use the high-res timer.

Comment 9

[Martin Bouladour]

Thank you for the answer.

Comment 10

[Avi Halachmi (:avih)]

I've got a report last week from a user by email that this also happens to him on two different real machines:

--- quote start ---

... On the other hand, jerkyness was appearing some hours after having launched firefox, even when clockres was reporting a timer resolution of 1ms.

But the fact that your bookmarklet [attachment 776049 [details] on bug 894128 - avih] only enumerates integer values between frames [it record intervals using performance.now() - avih] guided me to this bug.

...

In bug 902216, the complainer uses a virtual machine that could explain this drifting ; in my case these are real machines, using two different motherboards and graphics processors.

So I speculate that this issue is not only mine. So my workaround was to improve QueryPerformanceFrequency by enabling HPET (see http://www.neowin.net/forum/topic/1075781-tweak-enable-hpet-in-bios-and-os-for-better-performance-and-fps/) and now all is perfectly smooth.

This is obviously not a suitable solution for all users suffering from lack of smoothness, so I think that QPC drifting computation should be corrected in order to avoid these unwanted fallbacks to lower timer resolutions.

---- quote end ----

Even if not all of them are related, we do also have other bugs for "jerkiness after some time/hours", and we couldn't quite put our finger on the exact cause yet:

- Bug 822096 (janky scrolling) - it's not clear from the first comments that it starts janking after some time, but further comments confirm this. This bug is now believed to be event starvation, possibly related to "favor performance mode". The first major attempt at this was at bug 930793 (landed after a lot of work, backed out and now idle). The major related work these days happen on bug 996848 and related bugs and seems near completion.

- Bug 1001057 (customize animation becoming janky after a lengthy session). Not necessarily timing related though.

- And there have been other reports of janking after a while.

While the subject of events starvation seems unrelated to low resolution timers, I do have a hunch they might be. I have a vague recollection that under certain kinds of loads, performance.now() falls back to integral numbers reporting. We've seen this on windows xp at the very least, and our performance.now() mochitest even takes it into account.

Maybe the code from bug 822490 and bug 836869 somehow fallback to lesser mode if something is starved? I know it's vague, and I wish it wouldn't be, but vague is all I got right now.

Comment 11

[Avi Halachmi (:avih)]

(In reply to Avi Halachmi (:avih) from comment #10)
> While the subject of events starvation seems unrelated to low resolution
> timers, I do have a hunch they might be. I have a vague recollection that
> under certain kinds of loads, performance.now() falls back to integral
> numbers reporting. We've seen this on windows xp at the very least, and our
> performance.now() mochitest even takes it into account.

I remember now what how I concluded this: when I tested and updated the performance.now() test, the fallback to integral performance.now() numbers happened much more in debug builds than in release builds. This led me to asses that it's because debug builds are slower (so somehow equivalent to "more load"), and events starvation could also fall into the same area of perceived load.

Comment 12

[Avi Halachmi (:avih)]

Honza,

- Under what conditions will the timers fall back to low res?
- Could load or delayed event handling cause this?
- will it ever try to get back to high res after it went from high to low res timers?

Comment 13

[Honza Bambas (:mayhemer)]

(In reply to Avi Halachmi (:avih) from comment #12)
> Honza,
> 

First I want to make sure that by "timers" you mean TimeStamp::Now(), right?

If so, then:

> - Under what conditions will the timers fall back to low res?

When GTC and QPC values differ for more then 65ms more then 4 times during 5 seconds (or something close to it).  The difference is checked every time we execute TimeDuration d = timeStamp1 - timeStamp2;  it's hidden in the '-' overloaded operator

see http://www.janbambas.cz/queryperformancecounter-calibration-with-gettickcount/

> - Could load or delayed event handling cause this?

No.

> - will it ever try to get back to high res after it went from high to low
> res timers?

No.

Comment 14

[Avi Halachmi (:avih)]

(In reply to Honza Bambas (:mayhemer) from comment #13)
> First I want to make sure that by "timers" you mean TimeStamp::Now(), right?

Not sure exactly. The one which window.performance.now() ends up using, and which usually provides sub ms resolution values (unless in "low resolution timers" mode, which then ends up in integer values and IIRC with ~15.6 ms resolution).

Thanks for the rest. I still suspect that on some cases with "normal" hardware, something causes it to switch to "low resolution" even if it seems it shouldn't.

IIRC I've noticed it at least once in the past (in normal nightly and not in a VM), and apparently the user which I quoted on comment 10 also reports a similar issue which then ends up in "less smooth stuff" and integral performance.now() values (on two different systems, neither of which is a VM).

I'll try to follow the logic, maybe I'll notice a path or a case which may lead to this switch accidentally. I've also setup a script which reads a performance.now() value once a second and checks if it's float (good) or integer (bad - and shows an alert message), but on my current system it so far hasn't triggered even once for the few hours I've had this script running.

If you suspect that there could be a scenario which may cause an accidental switch to low-res timers, do share.

Comment 15

[enzomas]

Attachment: Script to notify when performance.now fallbacks to integer values

Comment 16

[enzomas]

Following Avi's logic, I created a scipt which calls performance.now() 3 times, and throws notifications when theses 3 calls return integer values (fallback to less precise timer) : see attachment 8716623 [details] .

I loaded this page in a tab, an waited to see what triggers notifications.

I found some testcases, one of them triggers the fallback everytime on my system :
- launch GPU-Z (https://www.techpowerup.com/gpuz/)
- execute PCI-express render test (click question mark)

In fact, I found that this test triggers high DPC latency (see DPC latency checker, http://www.thesycon.de/deu/latency_check.shtml) : when DPC latency gets temporarily high, FF falls back to low resolution timers.

Since these DPC latency peeks happen sometimes, I think the fallback must not be permanent. 

We should either add a mechanism to return to high-precision timers after some time, and/or add an option to disable the fallback on systems that are likely to encounter DPC latencies.

Comment 17

[Boris Zbarsky [:bzbarsky]]

It's worth filing a separate bug on making the fallback non-permanent...

Comment 18

[Avi Halachmi (:avih)]

Honza?

Comment 19

[Honza Bambas (:mayhemer)]

Definitely doable, but I will not have time to work on it.