1356533 - Excessive CPU usage by the content process (racing the refresh driver?) on eBay product page

Status: RESOLVED WORKSFORME

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

Description

[Jonathan Kew [:jfkthame]]

I'm seeing excessively high CPU usage (consistently around 120%, i.e. one core fully saturated, plus some extra) when viewing an eBay product page such as http://www.ebay.co.uk/itm/141655131065. This continues long after the page has entirely finished loading and no new painting is happening.

Profile: https://perf-html.io/public/18d9ae964679dc50a3e867803d26aa8e3f2abf7d/calltree/?thread=2 (though with current Nightly, not all of the profiler data seems to appear properly for me).

AFAICT we're ticking the refresh driver far too quickly here, whenever the tab is in the foreground. (Switching to a different tab causes the CPU usage to drop to more normal levels.)

Presumably, there's something on the page that is triggering the constant refresh-driver ticking, but we should try to avoid this: it doesn't take long for the page to spin up the fans on my MBPro, and of course it's killing the battery. :(

Comment 1

[:Gijs (he/him)]

It seems at least significant (49%) part of that profile is spent under nsRefreshDriver::DispatchAnimationEvents, and there a significant amount of time is in nsDocument::EnumerateSubDocuments, which itself seems to spend surprisingly large amounts of time destroying (and so, I assume, creating as well) documents and prescontexts either itself or in nested calls to itself. Moving to Core as I don't see any evidence there are frontend-related issues here.

Comment 2

[Jonathan Kew [:jfkthame]]

Moving this to DOM:Animation, as it seems like that's the source of a lot of the high CPU usage here -- even though nothing is actually being animated, AFAICS. (Is the page doing something dumb that causes this? Or are we spuriously firing off animation events when we shouldn't?)

Comment 3

[Mantaroh Yoshinaga[:mantaroh]]

I've investigated this profile. It looks like that it used the software refresh timer not hardware vsync-base refresh timer(VsyncRefreshDriver). I tried this eBay site with ASAP mode(layout.frame_rate=0), then the result was same to this phenomenon. (i.e. it occur much Tick due to not use vsync-base refresh timer)
I'm investigating other reason of using not vsync-base refresh driver now.

Jonathan,
Do you remember that whether you changed this preference?

Comment 4

[Mantaroh Yoshinaga[:mantaroh]]

Although it is not directly related to this bug, we will need to use AutoTArray instead of nsCOMArray in Tick() when accessing intersection observer[1].

[1] http://searchfox.org/mozilla-central/rev/6c2dbacbba1d58b8679cee700fd0a54189e0cf1b/layout/base/nsRefreshDriver.cpp#1897

Comment 5

[Jonathan Kew [:jfkthame]]

(In reply to Mantaroh Yoshinaga[:mantaroh] from comment #3)
> I've investigated this profile. It looks like that it used the software
> refresh timer not hardware vsync-base refresh timer(VsyncRefreshDriver). I
> tried this eBay site with ASAP mode(layout.frame_rate=0), then the result
> was same to this phenomenon. (i.e. it occur much Tick due to not use
> vsync-base refresh timer)
> I'm investigating other reason of using not vsync-base refresh driver now.
> 
> Jonathan,
> Do you remember that whether you changed this preference?

Interesting, thanks for looking into this. I don't remember having changed that pref.... but I looked in my profile, and sure enough, it was set to zero. So I must have touched it at some point. With the pref reset to the default, I no longer see the racing refresh driver.

I'm still curious why the issue shows up on this page, but not on other web pages in general, but if it only occurs with a non-default pref then it may be much less important. (Unless there are significant numbers of users who would get the software refresh timer by default, and therefore could be affected even if they haven't messed with hidden prefs.)

Note that a similar issue seems to affect the About window (see bug 1354913), and resetting the layout.frame_rate pref seems to have fixed that as well.

Comment 6

[Brian Birtles (:birtles, Feb 26~ parental leave)]

So it looks like CollectDocuments is a bit heavy-weight. However, it also appears IntersectionObserver is using the same pattern and in a less performant manner (using nsCOMArray instead of AutoTArray) but it doesn't show up in the profile since it is inlined in nsRefreshDriver::Tick, unlike the animation event handling which is wrapped in a separate function.

Mantaroh is going to just double-check that it really is CollectDocuments to blame (and nothing we do in the subsequent loop).

Even so, if a lot of users have set this pref to zero then we might have to find some workaround for this. Searching addons and Google and so on, it seems a number of users are setting this to values other than zero (e.g. 144) but I haven't seen any cases of setting it to zero except Talos testing.

Comment 7

[Mantaroh Yoshinaga[:mantaroh]]

I have confirmed that all the time is being spent gathering the subdocuments in CollectDocuments. If I remove all the animation-event related code from DispatchAnimationEvents, this method still shows up in the profile with about the same prominence.

Profiling Results:
[The case of removing animation-event] https://perfht.ml/2rWlJw7
[Before modifying] https://perfht.ml/2rWPBIP

Since CollectDocuments is also used for IntersectionObservers, I'm moving this to the DOM component since there doesn't seem to be anything animation-specific about it.

Furthermore, it appears that this bug only occurs if the user has set the layout.frame_rate to 0. Searching the add-on repository the only add-on that sets the pref to this value is the tart add-on so I don't expect users are regularly setting this preference to zero via add-ons. Searching Google, some people appear to be changing this pref to values like 144 for VR, but not to zero. So, at this stage I don't know why Jonathan's profile had this pref set to zero. Unless we have reason to believe other users might be have this pref similarly set, I suggest this bug should be P5 or even WONTFIX but I will leave that to the DOM triage lead to determine.

I will also file a separate bug for making IntersectionObserver use AutoTArray instead of nsCOMArray.

Comment 8

[Andrew Overholt [:overholt]]

Maybe Tobias knows what's up here?

Comment 9

[Chris Peterson [:cpeterson]]

QRC_NeedAnalysis: Assigning to Tobias for profile analysis for now

Comment 10

[Tobias Schneider [:tobytailor]]

> I will also file a separate bug for making IntersectionObserver use
> AutoTArray instead of nsCOMArray.

Did you already file a bug for this?

Comment 11

[Mantaroh Yoshinaga[:mantaroh]]

(In reply to Tobias Schneider [:tobytailor] from comment #10)
> > I will also file a separate bug for making IntersectionObserver use
> > AutoTArray instead of nsCOMArray.
> 
> Did you already file a bug for this?

Sorry, I've fixed it at bug 1367981.

Comment 12

[Tobias Schneider [:tobytailor]]

> Sorry, I've fixed it at bug 1367981.

I see, thanks for that. Do we still see excessive CPU usage after that fix?

Comment 13

[Jean Gong :jgong]

We will be running some tests with layout.frame_rate to 0.  I will keep this bug around until we see if there any bug that surface from it.

Comment 14

[Hiroyuki Ikezoe (:hiro)]

I had a look this somehow (actually I came from bug 1354501).  As for animation events, CollectDocuments() is bit expensive since it collects all descendant documents even if the descendant has no animations there.  Also nsIDocument::EnumerateSubDocuments() assumes that |aCallback| in the function might modify mSubDocument (bug 1293985), but luckily for checking whether the document has animations does not mutate anything.  So I think we can add another variant of EnumerateSubDocuments() for this bug.  Also the new function does not stop enumerating sibling documents because CollectDocuments() never returns false, so the new function looks like this;

typedef void (*nsSubDocEnumImmutableFunc)(const nsIDocument* aDocument, void* aData);
void EnumerateAllSubDocuments(nsSubDocEnumImmutableFunct aCallback, void* aData) const;

CCing Olli, since he might be interested in this.

Comment 15

[mirh]

Uh, I had forgot I had subscribed to this bug. 
Long story short though, I wanted to report how overall performance on ebay is incredibly faster now, compared to 3 months ago. 
Not sure if due to updates of the browser (I think I had FF55 beta back then, now FF56 stable), add-ons (for example, just this week keefox got perfectly webextension-ized) or website itself though.

Comment 16

[Hiroyuki Ikezoe (:hiro)]

mirh, thanks for the comment.  Now firefox 57 is the stable version, would you mind commenting about the performance on 57?  I am going to clone this bug if it's fine (and file a new bug for the case in comment 14).

Comment 17

[mirh]

I'm on 58b11 atm - though yes, ebay feels almost smooth as silk now. 

I went checking OP's actual problem then, and it seems to be still there tbh. CPU never goes idle when I visit that page, even after several minutes.

Comment 18

[Hiroyuki Ikezoe (:hiro)]

Closing as per comment 17.

Thank you, mirh!

Comment 19

[Hiroyuki Ikezoe (:hiro)]

(In reply to Hiroyuki Ikezoe (:hiro) from comment #14)
> I had a look this somehow (actually I came from bug 1354501).  As for
> animation events, CollectDocuments() is bit expensive since it collects all
> descendant documents even if the descendant has no animations there.  Also
> nsIDocument::EnumerateSubDocuments() assumes that |aCallback| in the
> function might modify mSubDocument (bug 1293985), but luckily for checking
> whether the document has animations does not mutate anything.  So I think we
> can add another variant of EnumerateSubDocuments() for this bug.  Also the
> new function does not stop enumerating sibling documents because
> CollectDocuments() never returns false, so the new function looks like this;
> 
> typedef void (*nsSubDocEnumImmutableFunc)(const nsIDocument* aDocument,
> void* aData);
> void EnumerateAllSubDocuments(nsSubDocEnumImmutableFunct aCallback, void*
> aData) const;
> 
> CCing Olli, since he might be interested in this.

Filed bug 1433336 for this.

Comment 20

[mirh]

(In reply to Hiroyuki Ikezoe (:hiro) from comment #18)
> Closing as per comment 17.
> 
> Thank you, mirh!

The only thing I confirm there is about what I said in comment 15.
As per what's in the first post.. For as much as I'm not seeing "120% cpu usage" it's not wrong to say you never go idle on that product page. 

I'm getting like 5-10% cpu usage on my core 2 duo though - so I guess somebody might already call it a day.