Closed Bug 1106115 Opened 5 years ago Closed 4 years ago

System Timer Resolution locked to 1 ms when using requestAnimationFrame in Firefox

Categories

(Core :: XPCOM, defect)

33 Branch
x86_64
Windows 7
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla42
Tracking Status
firefox42 --- fixed

People

(Reporter: r.riedl, Assigned: tnikkel)

References

Details

(Keywords: regression)

Attachments

(2 files, 1 obsolete file)

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:33.0) Gecko/20100101 Firefox/33.0
Build ID: 20141113143407

Steps to reproduce:

Run clockres form Sysinternals viewing the current system timer resolution (normally 15.6 ms), open any pdf file in Firefox, run clockres again (now 1ms). Close Tab with pdf or browse to another site, run clockres again (still 1 ms). Timer resolution is only restored to 15.6ms when closing Firefox.




Actual results:

system timer resolution won't be reset as long as firefox is open


Expected results:

Due to my tests Adobe Reader itself is't changing timer resolution, Firefox should avoid changing timer resolution as well when viewing pdf files.

Problem is closely related to, just another was of triggering this behavour:
https://bugzilla.mozilla.org/show_bug.cgi?id=655413
Reporter, to be clear, this only happens when viewing PDFs with Adobe reader, rather than with Firefox's builtin PDF viewer? Does it happen with other plugins, like Flash or Silverlight?

Benjamin, any idea what's going on here? Did we consciously revert bug 655413, did that really only apply to flash (fix doesn't look like that to me, naively...) and/or is this related?
Component: Untriaged → IPC
Flags: needinfo?(r.riedl)
Flags: needinfo?(benjamin)
Product: Firefox → Core
Happens with internal Pdf viewer!
Flags: needinfo?(r.riedl)
I did some further testing an there is no Problem when using Adobe Acrobat Plugin.
It really only happens on the builtin Pdf-Viewer in Firefox.
Does PDF.js even use a separate process outside e10s? I didn't think we consigned things like this to their own process yet (I know Shumway is planning to, but..).

There's several places where we call timeBeginPeriod and timeEndPeriod aside from the location that was touched in bug 655413:
http://dxr.mozilla.org/mozilla-central/search?q=timeBeginPeriod
http://dxr.mozilla.org/mozilla-central/search?q=timeEndPeriod

I imagine it wouldn't be too hard to add a few counters for each category and see which one fails to go back to 0 after the pdf is closed.
Why is this in Core:IPC? Do we have any evidence that this is IPC-related (does it only happen with e10s enabled, for example)?

rvitillo, is this something you're interested in?
Flags: needinfo?(benjamin) → needinfo?(rvitillo)
(In reply to Benjamin Smedberg  [:bsmedberg] from comment #5)
> Why is this in Core:IPC? Do we have any evidence that this is IPC-related
> (does it only happen with e10s enabled, for example)?

It's because I initially misunderstood and thought this was the acrobat plugin in Firefox because comment #0 mentioned bug 655413. Sorry. Moving to pdfjs instead.
Component: IPC → PDF Viewer
Product: Core → Firefox
Blocks: power
Flags: needinfo?(rvitillo)
Closing the browser is not necessary, waiting a minute or two will do.

Here's the regression(?)-range for switching to 1ms, which didn't happen before:
Last good revision: bc108d2ce8d1 (2013-02-06)
First bad revision: 04e13fc9dbff (2013-02-07)
Pushlog:
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=bc108d2ce8d1&tochange=04e13fc9dbff
According to the regression range it's probably bug 835954 that regressed this?
Blocks: 835954
Keywords: regression
Yury, any idea what could cause this?
Flags: needinfo?(ydelendik)
Tried regular web page at http://mozilla.github.io/pdf.js/web/viewer.html -- it has same effect, so it's not the internal PDF viewer per se, but some Gecko API that leaves this state. Trying to create a smaller test case.
A simple requestAnimationFrame call will trigger this state.
Flags: needinfo?(ydelendik)
Removing a regression tag since it's not a PDF viewer regression -- just happens PDF.js started using requestAnimationFrame in bug 835954.
No longer blocks: 835954
Component: PDF Viewer → Untriaged
Keywords: regression
Summary: System Timer Resolution locked to 1 ms when viewing pdf in Firefox → System Timer Resolution locked to 1 ms when using requestAnimationFrame in Firefox
Blocks: 731974
Component: Untriaged → XPCOM
Keywords: regression
Product: Firefox → Core
Status: UNCONFIRMED → NEW
Ever confirmed: true
It could be related, but when using requestAnimationFrame or similar (possibly internal) frame-callback facilities, the refresh driver sets the (system) timer resolution to 1ms in order to accurately time the next frame.

This drops back to the normal timer resolution after 90s IIRC if there were no further rAF calls, in order to not change the timers resolution too often. It's by design.

Project silk vsync implementation might be able to get away without using higher timer resolution (by using vsync-blocking rather than timers), but we're not there yet.

So it's possible that some changes in pdf.js are now using requestAnimationFrame or some other frame-callback functionality, and Gecko responds by increasing the timers resolution temporarily.
Probably because SetHighPrecisionTimerEnabled:

http://dxr.mozilla.org/mozilla-central/layout/base/nsRefreshDriver.cpp#l921

isn't getting turned off when it's supposed to.  We enable high precision timers when requestAnimationFrame is being used, and we're supposed to turn it off when we're done, but apparently that doesn't happen...
Comment 7 suggests that it does.

So, this is just expected behavior, then?
Will other browsers also hog the battery during requestAnimationFrame (and after 90s)?
It's the designed behavior when frame timing accuracy is required, and 90s is, as the comment says, arbitrary. It might work well enough with 10s or 5s or 1s instead of 90.

vlad, any reason not to change this to 1s?
Flags: needinfo?(vladimir)
Is is proper behavior to not lower the interval when e.g. changing from www.google.com to bugzilla.mozilla.org in the same tab, but lowering the interval when opening a new tab, even if it's just set to show about:blank?
Or is that because of the tab-animation when opening the new tab?
Most probably the tab animation.
- should we fix http://mxr.mozilla.org/mozilla-central/source/browser/base/content/tabbrowser.xml#1745 to not use requestAnimationFrame, then? :-\

- Reinhard, can you confirm comment #7 on your machine with pdfjs? (so, after closing pdfjs and browsing elsewhere, then waiting about 90 seconds, running clockres shows 15.6ms again)
Flags: needinfo?(r.riedl)
(In reply to :Gijs Kruitbosch from comment #21)
> - should we fix
> http://mxr.mozilla.org/mozilla-central/source/browser/base/content/
> tabbrowser.xml#1745 to not use requestAnimationFrame, then? :-\

Probably not. rAF and other animations are used frequently enough on the web anyway, and regardless, for almost any smooth animation we need the high resolution timers right now (see comment 13 about project Silk).

If the higher timers resolution results in meaningfully/measurably higher power consumption (numbers would be nice), then we should change 90s to a shorter timeout, or wait for project Silk which will hopefully get the correct timing without using high-res timers.

But avoiding smooth animation within Firefox just to avoid triggering higher timers resolution is most probably an incorrect approach.
Yes i can confirm
JS uses the NotifyDidPaint notification [1] to reduce the slice budget for incremental GCs. I feel like this should use the same mechanism - or if it already does, then this might be affecting more than just the system timer resolution. Other than that, 90 seconds does seem like a long time.

[1] http://dxr.mozilla.org/mozilla-central/source/layout/base/nsRefreshDriver.cpp#1383
(In reply to Avi Halachmi (:avih) from comment #22)

> If the higher timers resolution results in meaningfully/measurably higher
> power consumption (numbers would be nice), then we should change 90s to a
> shorter timeout, or wait for project Silk which will hopefully get the
> correct timing without using high-res timers.

According to a MS paper, setting the timer resolution to 1 ms can reduce the battery run time on mobile systems by as much as 25 percent (see http://download.microsoft.com/download/3/0/2/3027D574-C433-412A-A8B6-5E0A75D5B237/Timer-Resolution.docx)
Could this be one of the reasons for the higher power usage we have compared to Chrome, as reported by agal[1]?

Note that that was about power usage under OS X 10.10, but I'd expect high resolution timers to affect power usage under all operating systems.

[1] https://groups.google.com/forum/#!topic/mozilla.dev.platform/8hA8smMecRg
(In reply to Till Schneidereit [:till] from comment #26)
> Could this be one of the reasons for the higher power usage we have compared
> to Chrome, as reported by agal[1]?
> 
> Note that that was about power usage under OS X 10.10, but I'd expect high
> resolution timers to affect power usage under all operating systems.
> 
> [1] https://groups.google.com/forum/#!topic/mozilla.dev.platform/8hA8smMecRg

The high resolution timers is a Windows thing. AFAIK we don't have it on Linux or OS X.
I tested this on my machine, and the timer resolution stays at 1ms as long as the PDF is open (beyond 90 seconds). So this bug should really be about fixing pdf.js
> I tested this on my machine, and the timer resolution stays at 1ms as long as the PDF is open (beyond 90 seconds). So this bug should really be about fixing pdf.js

requestAnimationFrame is used in PDF in two places: during initial start up and during page painting. Removing rAF from the latter mean fall back to the setTimeout or Promises microtask queue. See also https://github.com/mozilla/pdf.js/issues/4762.

Please define STR and expected behavior, since the initial description of the problem states "Firefox should avoid changing timer resolution as well when viewing pdf files", which is somewhat won't fix.
(In reply to Avi Halachmi (:avih) from comment #22)
> (In reply to :Gijs Kruitbosch from comment #21)
> > - should we fix
> > http://mxr.mozilla.org/mozilla-central/source/browser/base/content/
> > tabbrowser.xml#1745 to not use requestAnimationFrame, then? :-\
> 
> Probably not. rAF and other animations are used frequently enough on the web
> anyway, and regardless, for almost any smooth animation we need the high
> resolution timers right now (see comment 13 about project Silk).
> 
> If the higher timers resolution results in meaningfully/measurably higher
> power consumption (numbers would be nice), then we should change 90s to a
> shorter timeout, or wait for project Silk which will hopefully get the
> correct timing without using high-res timers.

Project silk and triggering off proper vsync is the right solution here.  We can lower that 90s, I don't have any strong opinion there; though there (iirc) are issues with making too many calls to SetHighPrecisionTimerEnabled on some older hardware.

I'm curious as to why the precision is never reduced, though; it stays at 1ms even after closing the pdf.js tab (or presumably anything else using rAF)?  We should double check that we do go back to a lower precision correctly after the 90s (or whatever).
Flags: needinfo?(vladimir)
(In reply to Yury Delendik (:yury) from comment #29)
> Please define STR and expected behavior, since the initial description of
> the problem states "Firefox should avoid changing timer resolution as well
> when viewing pdf files", which is somewhat won't fix.

STR & expected behavior for one use-case:

1. Using Win 7 or earlier, first confirm the system timer resolution is 15.6ms, using ClockRes
http://technet.microsoft.com/en-us/sysinternals/bb897568.aspx
2. Open a pdf file with pdf.js in Firefox, wait for it to load and finish painting
3. Leave browser idle and wait 90 seconds (or longer to be sure), check system timer resolution again

Expected behavior: 90 seconds after the PDF was opened, the system timer resolution should return to 15.6ms
Actual behavior: the timer resolution remains permanently stuck at 1ms as long as the PDF file is open, even when the user isn't doing anything with the opened PDF file
Regression-range for comment 31:
Last good revision: cbe4f69c2e9c (2014-05-27)
First bad revision: e017c15325ae (2014-05-28)
Pushlog:
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=cbe4f69c2e9c&tochange=e017c15325ae
Bug 1016308 has fix for https://github.com/mozilla/pdf.js/issues/4762 (see also comment 29). Trying to create reduced test case.
Flags: needinfo?(ydelendik)
(In reply to Vladan Djeric (:vladan) from comment #31)
> Expected behavior: 90 seconds after the PDF was opened, the system timer
> resolution should return to 15.6ms
> Actual behavior: the timer resolution remains permanently stuck at 1ms as
> long as the PDF file is open, even when the user isn't doing anything with
> the opened PDF file

If you close the PDF file, does it go back down?
(In reply to Vladimir Vukicevic [:vlad] [:vladv] from comment #34)
> If you close the PDF file, does it go back down?

Yes, it does
(In reply to Vladan Djeric (:vladan) from comment #35)
> (In reply to Vladimir Vukicevic [:vlad] [:vladv] from comment #34)
> > If you close the PDF file, does it go back down?
> 
> Yes, it does

.. I meant "yes, it does, 90 seconds after closing the pdf"
(quick update is somebody has ideas)

While in a process of creating minimal test case, I found that:
- Not all files suitable for STR in comment 31, e.g. http://www.education.gov.yk.ca/pdf/pdf-test.pdf works fine, but http://cdn.mozilla.net/pdfjs/tracemonkey.pdf shows the problem
- I was tracing all rAF calls in PDF.js -- after PDF loading and pages painting, no calls of rAF are made (so looks like bad logic not on the PDF.js side)
- In files with the problem, nsRefreshDriver::StopTimer at http://mxr.mozilla.org/mozilla-central/source/layout/base/nsRefreshDriver.cpp#910 is not getting called (in comparison with working files)
That was a hard and bizarre one: the animated out-of-view gif does not let to reduce timer resolution after requestAnimationFrame is used.

ImageRequestCount() never reaches 0 at http://mxr.mozilla.org/mozilla-central/source/layout/base/nsRefreshDriver.cpp#1154
Attachment #8533707 - Attachment is obsolete: true
Flags: needinfo?(ydelendik)
Sounds a bit like bug 968123 or bug 987212? Maybe the layout guys should take a look
Flags: needinfo?(tnikkel)
Out of view animated gifs will currently keep the refresh driver active as the bugs in comment 39 point out (which we should fix). But that shouldn't force the refresh driver to stay in high precision mode. My guess is that there is a bug in the refresh driver code. When the last rAF callback is removed nsRefreshDriver::RevokeFrameRequestCallbacks should be called, and ConfigureHighPrecision should call SetHighPrecisionTimersEnabled(false) and that should eventually result in timeEndPeriod(1) being called somehow. Why is that not happening?
Flags: needinfo?(tnikkel)
Flags: needinfo?(r.riedl)
Attached patch patchSplinter Review
This was a simple mistake in the code to manage high precision mode. Description in the patch.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=21c7958cdcb8

Mason, are you familiar with this code?
Assignee: nobody → tnikkel
Attachment #8640962 - Flags: review?(mchang)
Comment on attachment 8640962 [details] [diff] [review]
patch

Review of attachment 8640962 [details] [diff] [review]:
-----------------------------------------------------------------

I'm not really familiar with this code, but from comment 40, shouldn't we be doing "When the last rAF callback is removed nsRefreshDriver::RevokeFrameRequestCallbacks should be called" instead of directly calling ConfigureHighPrecision? From commit logs, looks like Vlad wrote this code, so redirecting review to him.
Attachment #8640962 - Flags: review?(mchang) → review?(vladimir)
(In reply to Mason Chang [:mchang] from comment #42)
> I'm not really familiar with this code, but from comment 40, shouldn't we be
> doing "When the last rAF callback is removed
> nsRefreshDriver::RevokeFrameRequestCallbacks should be called" instead of
> directly calling ConfigureHighPrecision?

In the "normal" sequence of events some script asks for a RAF callback, ScheduleFrameRequestCallbacks is called, the document is added to mFrameRequestCallbackDocs. The refresh driver ticks, it empties mFrameRequestCallbackDocs into a local variable, and then calls the callbacks. If the script wants another callback is has to ask for one (potentially in its RAF callback). Frame requests are only revoked if the script asks for a RAF and then decides to cancel it before it gets a callback for some reason, or the document is going away, or enters an "events suppressed" mode. When RAF callbacks are called normally during a refresh driver tick they don't get revoked.
Comment on attachment 8640962 [details] [diff] [review]
patch

Looks right to me.  This.. hm.  I know when I originally landed this code we were properly dropping out of high precision mode, but perhaps that was an accident due to something else triggering ConfigureHighPrecision?
Attachment #8640962 - Flags: review?(vladimir) → review+
https://hg.mozilla.org/mozilla-central/rev/ad7a4bbda021
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla42
You need to log in before you can comment on or make changes to this bug.