Closed Bug 1615564 Opened 4 years ago Closed 4 years ago

Lots of time spend in Window.clearTimeout after watching movies on https://www.tvnow.de

Categories

(Core :: DOM: Core & HTML, enhancement, P3)

enhancement

Tracking

()

VERIFIED FIXED
mozilla78
Tracking Status
firefox78 --- verified

People

(Reporter: whimboo, Assigned: smaug)

References

(Blocks 2 open bugs)

Details

(Keywords: memory-footprint, perf, power)

Attachments

(3 files)

As already noticed over on bug 1578161 a lot of time is spent in Window.clearTimeout. This is not visible immediately, but after watching some videos on that page. In my case I tried to reproduce it for https://www.tvnow.de/serien/unter-uns-20/2020-02

After watching one of those freely available episodes, and the page forwarded to the next one automatically, I have seen that the CPU was spinning up a lot even with the page not visible and the browser in hidden. Also the memory usage increases a lot.

Here a created profile: https://perfht.ml/37pqsd5

As talking to Olli it looks like the page is creating a lot of timers, which need to be removed again. So this may be a webcompat issue, but for now I'm filing it under DOM.

Speaking about the CPU load it keeps staying at 100% for the specific web content process.

I had it again today. It was actually after waking up the MBP from hibernation. Maybe this mode caused that behavior?

Also I'm using NoScript and switching to temporarily trust all, and immediately revoke it again, fixed it. When I see it the next time I will record a gecko profile while doing these steps.

Type: defect → enhancement
Priority: -- → P3

I hit it today again after I paused the playback and put the tab into background. Not sure when the higher CPU load actually started. Also it was very hard to get the video played again, because clicking the (overlay) play button didn't cause any reaction. Maybe that is due to the higher CPU load and maybe delayed event handling? After several clicks it worked.

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #4)

Also I'm using NoScript and switching to temporarily trust all, and immediately revoke it again, fixed it. When I see it the next time I will record a gecko profile while doing these steps.

It's actually enough to simply reload the page. Then the CPU load will return to a normal level after a couple of seconds.

Also Olli's example testcase above doesn't cause this behavior.

Ok, so this seems to be a timing thing. Over the past two weeks the following steps have been qualified to reproduce the problem:

  1. Open a new tab and pin it
  2. Navigate to eg https://www.tvnow.de/serien/unter-uns-20
  3. Start watching the video and seek close to the end of part 1
  4. Continue watching and let it switch to part 2
  5. Pause the playback
  6. Navigate away and let the tab sit there for one or two hours

At some point you will notice that Firefox consumes 100% CPU load for this tab. In such a situation you will be able to see the massive calls into window.clearTimeout.

Once you reload the page, and wait some seconds everything is fine again.

Olli, would you have the time to try that? Not sure what else I could do to give more information. Thanks!

Flags: needinfo?(bugs)

Olli, is there anything I can further do to help getting this investigated? Maybe creating a long-term baseline profile with only the markers added so we can see where the setTimeouts are all set? Not sure if that is possible right now.

I'm looking this. Unfortunately out timeout code is rather complicated.

And perhaps the issue is that no one is setting the timers, but some script is calling clearTimeout with invalid id.

Component: DOM: Events → DOM: Core & HTML

https://treeherder.mozilla.org/#/jobs?repo=try&revision=84b198aadb81d04cb3cb328d8a99dd755d02827e

Henrik, want to test a tryserver build (once such is ready)?
(hopefully the builds don't crash immediately :) )

Flags: needinfo?(bugs) → needinfo?(hskupin)

Sure. I could do once the code compiles. Can you fix the timerid problem and push again? Should I use an opt or debug build then?

Assignee: nobody → bugs
Status: NEW → ASSIGNED
Flags: needinfo?(hskupin) → needinfo?(bugs)

oh, lovely, it compiled locally. Pushing again.

Flags: needinfo?(hskupin)

I tried this build but I cannot get anything to play beside the advertisement as shown first for every content. Maybe the changes broke some behavior?

Mind trying yourself at https://www.tvnow.de/serien/unter-uns-20/2020-05? Just click the play button and wait until the advertisement is done. You should see a black screen then.

Beside that I also face problems with other media content on this side which cannot be played due to broken/missing DRM. Maybe something is not correctly enabled in a try build and we would have to generate a Nightly build?

Flags: needinfo?(hskupin) → needinfo?(bugs)

I get DRM error.
...ah I can get passed that by accepting installing drm components on Nightly

Flags: needinfo?(bugs)

Hey Bryce, can you help us here to get around the DRM error? Please see my comment 14 for details. Thanks!

Flags: needinfo?(bvandyk)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #16)

Hey Bryce, can you help us here to get around the DRM error? Please see my comment 14 for details. Thanks!

Looking at the edit in comment 15 it sounds like this may be a matter of toggling DRM on in Options -> General. Let me know if I'm mistaken and I can look further.

Flags: needinfo?(bvandyk)

That preference is turned on for me. It's the reason why it is puzzling.

Flags: needinfo?(bvandyk)

Debugged out of band. Please reach out again as needed.

Flags: needinfo?(bvandyk)

I tested the try build for a couple of hours, and also after putting MacOS in sleep mode during the night. It all looks fine and the improvements are outstanding. There is no longer a Firefox parent process around that keeps a core busy at 100%. So not only a performance improvement, but also counts a lot to power usage reduction. Thanks a lot Olli!

Keywords: power
Pushed by opettay@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/1c58f39177c0
clearing timeouts should be O(1) r=farre

Why I can't reland with the trivial fix...

Flags: needinfo?(bugs)

(In reply to Olli Pettay [:smaug] from comment #23)

Why I can't reland with the trivial fix...

Because it is still marked as closed. With a backout it needs to be reopened, and I assume that's automatically done by the sheriffs or a script? Not sure why that didn't happen here.

Flags: needinfo?(aryx.bugmail)

On Thursday, a sheriff had to oops hg backout instead of hg oops which puts the bug number before the revision hash and this doesn't get picked up by the Phabricator script which reopens revisions. Sorry about that.

Flags: needinfo?(aryx.bugmail)
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla78

After two days using this site excessively I can verify that the CPU load is all normal now. No more process running at 100% in the background and the battery holds way longer. Now I cannot await to see it in beta soon. Thanks again Olli!

Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: