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

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Reinhard Riedl]

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

Comment 1

[:Gijs (he/him)]

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?

Comment 2

[Reinhard Riedl]

Happens with internal Pdf viewer!

Comment 3

[Reinhard 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.

Comment 4

[Emanuel Hoogeveen [:ehoogeveen]]

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.

Comment 5

[Benjamin Smedberg]

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?

Comment 6

[:Gijs (he/him)]

(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.

Comment 7

[Elbart]

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

Comment 8

[Tim Taubert [:ttaubert] (inactive)]

According to the regression range it's probably bug 835954 that regressed this?

Comment 9

[Tim Taubert [:ttaubert] (inactive)]

Yury, any idea what could cause this?

Comment 10

[Yury Delendik (:yury)]

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.

Comment 11

[Yury Delendik (:yury)]

Attachment: Minimal test case to reproduce the issue

A simple requestAnimationFrame call will trigger this state.

Comment 12

[Yury Delendik (:yury)]

Removing a regression tag since it's not a PDF viewer regression -- just happens PDF.js started using requestAnimationFrame in bug 835954.

Comment 13

[Avi Halachmi (:avih)]

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.

Comment 14

[Nathan Froyd [:froydnj]]

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 15

[Avi Halachmi (:avih)]

It's supposed to go off after 90s: http://dxr.mozilla.org/mozilla-central/source/layout/base/nsRefreshDriver.cpp#960

Comment 16

[Nathan Froyd [:froydnj]]

Comment 7 suggests that it does.

So, this is just expected behavior, then?

Comment 17

[Masatoshi Kimura [:emk]]

Will other browsers also hog the battery during requestAnimationFrame (and after 90s)?

Comment 18

[Avi Halachmi (:avih)]

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?

Comment 19

[Elbart]

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?

Comment 20

[Avi Halachmi (:avih)]

Most probably the tab animation.

Comment 21

[:Gijs (he/him)]

- 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)

Comment 22

[Avi Halachmi (:avih)]

(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.

Comment 23

[Reinhard Riedl]

Yes i can confirm

Comment 24

[Emanuel Hoogeveen [:ehoogeveen]]

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

Comment 25

[Roberto Agostino Vitillo (:rvitillo)]

(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)

Comment 26

[Till Schneidereit [:till]]

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

Comment 27

[Avi Halachmi (:avih)]

(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.

Comment 28

[Vladan Djeric (:vladan)]

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

Comment 29

[Yury Delendik (:yury)]

> 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.

Comment 30

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

(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).

Comment 31

[Vladan Djeric (:vladan)]

(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

Comment 32

[Elbart]

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

Comment 33

[Yury Delendik (:yury)]

Bug 1016308 has fix for https://github.com/mozilla/pdf.js/issues/4762 (see also comment 29). Trying to create reduced test case.

Comment 34

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

(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?

Comment 35

[Vladan Djeric (:vladan)]

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

Yes, it does

Comment 36

[Vladan Djeric (:vladan)]

(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"

Comment 37

[Yury Delendik (:yury)]

(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)

Comment 38

[Yury Delendik (:yury)]

Attachment: Minimal test case to reproduce the issue

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

Comment 39

[Vladan Djeric (:vladan)]

Sounds a bit like bug 968123 or bug 987212? Maybe the layout guys should take a look

Comment 40

[Timothy Nikkel (: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?

Comment 41

[Timothy Nikkel (:tnikkel)]

Attachment: patch

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?

Comment 42

[Mason Chang [Inactive] [: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.

Comment 43

[Timothy Nikkel (:tnikkel)]

(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 44

[Vladimir Vukicevic [:vlad] [:vladv] (needinfo me, slow to respond)]

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?

Comment 45

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/ad7a4bbda021

Comment 46

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/ad7a4bbda021