1200028 - High CPU usage on a fujitsu-general.com page

Status: RESOLVED DUPLICATE of bug 1381071

(Core :: CSS Parsing and Computation, defect)

Description

[Alice0775 White]

This is Firefox only problem.
And this is not a recent regression, the high CPU usage is reproduced on Firefox4 at least.

Steps To reproduce:
1. Open the URL ( http://www.fujitsu-general.com/jp/products/aircon/howtouse/ )

Actual Results:
100% CPU usage

Gecko profiler:
http://people.mozilla.org/~bgirard/cleopatra/#report=6df79daa51610d3b486f6f4da2dbb258701ac982

Comment 1

[Alice0775 White]

Attachment: zipped page for the record

Comment 2

[Mayank Bansal]

confirmed. This page continuously uses 100% of 1 core.

Comment 3

[Nicholas Nethercote [inactive]]

With this page on my Mac I see Nightly using about 70% CPU and having over 300
wakeups/s, both almost entirely in the child process, and the processor+memory
power estimate is ~14.3 Watts.

With Safari I see ~0% CPU and ~25 wakeups/s, and the processor+memory power
estimate is ~3.5 Watts.

With Chrome I see ~0% CPU and ~25 wakeups/s, and the processor memory power 
estimate is ~4.3 Watts.

Comment 4

[Nicholas Nethercote [inactive]]

Attachment: Relevant part of http://www.fujitsu-general.com/resources/js/plugin.js

I did some ad hoc instrumentation of timer firings and found that in 60 seconds one particular JS timer fired 5800 times, i.e ~97 times per second.

The relevant code is from the "malihu jquery custom scrollbar plugin", v3.0.8. I've attached part of it. There's a setTimeout() call inside o(), near the top. When it fires if some conditions are met then calls o() again, thus re-initializing the timer.

The conditions that must be met involve malihu-specific properties. Explanations from http://manos.malihu.gr/jquery-custom-content-scroller/:

- updateOnContentResize: "Update scrollbar(s) automatically on content, element or viewport resize."

- updateOnSelectorChange: "Update scrollbar(s) automatically when the amount and size of specific selectors changes."

- updateOnImageLoad: "Update scrollbar(s) automatically each time an image inside the element is fully loaded."

It looks like the code won't re-initialize the timer unless it thinks that one of those properties has been set. And this seems to be happening in Firefox even when I don't interact with Firefox or the page at all, and even when Firefox is in the background and not visible.

I don't understand why the timer is firing ~97 times per second. The timer length is 60ms which suggests it should be firing ~16 times per second.

Comment 5

[Nicholas Nethercote [inactive]]

> The relevant code is from the "malihu jquery custom scrollbar plugin",
> v3.0.8. I've attached part of it.

The original code, or at least a slightly modified version (but much easier to read) is here: 
https://github.com/malihu/malihu-custom-scrollbar-plugin/blob/f617bb9bbb16791d95a22157bb3180e7d9098519/js/uncompressed/jquery.mCustomScrollbar.js#L1871

I did some debugging with a local copy of the code and saw that the |updateOnSelectorChange| property was undefined, but |updateOnContentResize| and |updateOnImageLoad| are both true, due to being set here:
https://github.com/malihu/malihu-custom-scrollbar-plugin/blob/f617bb9bbb16791d95a22157bb3180e7d9098519/js/uncompressed/jquery.mCustomScrollbar.js#L263

This 60Hz loop will always execute if _autoUpdate() is called without its "rem" argument being set, as happens here:
https://github.com/malihu/malihu-custom-scrollbar-plugin/blob/f617bb9bbb16791d95a22157bb3180e7d9098519/js/uncompressed/jquery.mCustomScrollbar.js#L575

It looks like the 60Hz loop can be set up for multiple selectors; this might explain why we see 97Hz in practice, because there might be six of these going concurrently:
https://github.com/malihu/malihu-custom-scrollbar-plugin/blob/f617bb9bbb16791d95a22157bb3180e7d9098519/js/uncompressed/jquery.mCustomScrollbar.js#L494

So this all makes rough sense, but its not clear why Safari and Chrome seemingly don't spin these 60Hz loops.

Comment 6

[Nicholas Nethercote [inactive]]

> So this all makes rough sense, but its not clear why Safari and Chrome
> seemingly don't spin these 60Hz loops.

I just stepped through the code in both the Firefox and Chrome debuggers. The loops appear to be executing as expected in both browsers.

In the Firefox dev tools' waterfall view I see that every 6th or so time around the 60Hz loop there are four "Recalculate Style" events showing up. Their "Restyle Hint" is "CSSTransitions".

Comment 7

[Nicholas Nethercote [inactive]]

Looking at Alice's cleopatra link (in comment 0) and also the dev tools profiler, both also point at the 60Hz loop ("o/h[0].autoUpdate" in the profiles) as triggering calls into jQuery functions with names like Jb, .css, Xb, Yb, m.fn[d], m.access, and they cause CSS activity within Gecko.

Looking at the unminified code, I think it's the calls to jQuery's outerHeight() and outerWidth() that are causing Gecko's CSS code to be activated.

Comment 8

[Nicholas Nethercote [inactive]]

Selecting "invert callstack" in Cleopatra makes things clearer. Here are the top four entries for a portion of the recording:

> 21.8%  nsDefaultStringComparator::operator()()
> 21.3%  FindInReadable_Impl()
> 14.4%  SelectorMatches()
> 11.2%  RuleHash::EnumerateAllRules()

That's almost 70% in CSS-related stuff. (If you unfold the call stacks more it's clear that the generic functions in that list are called by CSS-related functions.)

Comment 9

[Cameron McCormack (:heycam)]

Looking a bit further up the call stack, there are five-level deep calls to nsComputedDOMStyle::GetStyleContextForElementNoFlush, which indicates that the script is probably poking at computed style for an element within a display:none element subtree.  And it looks like it is doing this for 10 different properties.  Each time one of this properties is looked up, we re-resolve the style context for the target element (and its four display:none ancestors), which is why we're running selector matching so much.

It seems like we could be more clever about caching the style context that we compute when we can't get one off the frame.  We could skip nulling out mStyleContextHolder when we have to resolve a new style context, and then somehow invalidate it later on.  Does that sound feasible Boris?  The simplest solution I can think of currently is to have a document generation counter that we check to see if we are awaiting (or already flushed) pending style/layout.

Comment 10

[Boris Zbarsky [:bzbarsky]]

Oh, hmm.  Yeah, that would work; clearly if we don't need a style flush then we can use the old style context.

We would also need to invalidate the cache if the style context is destroyed, though.  Primarily that means if the presshell we got it from goes away; I think that's the only way it can get destroyed while we hold a ref to it.

Comment 11

[Boris Zbarsky [:bzbarsky]]

Oh, and the general right architectural solution here is to attach style contexts to _elements_, not frames.  But that's a lot more work.

Comment 12

[Nicholas Nethercote [inactive]]

(In reply to Cameron McCormack (:heycam) from comment #9)
> 
> It seems like we could be more clever about caching the style context that
> we compute when we can't get one off the frame.

heycam gave me a hacky proof-of-concept patch to test this. I did 30 second processor+power measurements with tools/power/rapl:

- Nightly: 14.0 W
- heycam:   7.8 W
- Chrome:   4.1 W
- Safari:   3.3 W

So that removes 58% of the difference between Nightly and Safari.

Comment 13

[Nicholas Nethercote [inactive]]

The Animation Inspector shows that there are seven or eight animations on each of the two big buttons near the top, if I understand it correctly.

Comment 14

[Nicholas Nethercote [inactive]]

(In reply to Nicholas Nethercote [:njn] from comment #13)
> The Animation Inspector shows that there are seven or eight animations on
> each of the two big buttons near the top, if I understand it correctly.

Actually, it's not the buttons, but something else. I'm a bit confused by the animation inspector.

The CSS properties being animated are: border-{bottom,left,right,top}-color, color, -moz-column-rule-color, outline-color, and text-decoration-color.

Comment 15

[Cameron McCormack (:heycam)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=04fbd39d3cd6

Comment 16

[Nicholas Nethercote [inactive]]

(In reply to Cameron McCormack (:heycam) from comment #15)
> https://treeherder.mozilla.org/#/jobs?repo=try&revision=04fbd39d3cd6

Here are some stats (from tools/power/rapl and powermetrics) for this patch when 
sitting idle on http://www.fujitsu-general.com/jp/products/aircon/howtouse/ for
30 seconds on a Mac.

Before:

>     total W = _pkg_ (cores + _gpu_ + other) + _ram_ W
> #01 14.59 W = 13.21 ( 5.72 +  0.00 +  7.48) +  1.38 W
> 
> 1 sample taken over a period of 30.000 seconds
> 
> Name                               ID     CPU ms/s  User%  Deadlines (<2 ms, 2-5 ms)  Wakeups (Intr, Pkg idle)  GPU ms/s
> com.apple.Terminal                 293    671.56                                      363.84  34.95             0.00
>   plugin-container                 54117  624.94    98.35  287.34  3.13               307.73  15.66             0.00
>   firefox                          54116  37.92     57.73  0.97    2.33               55.61   19.12             0.00
>   Terminal                         694    8.68      93.10  0.00    0.00               0.40    0.13              0.00

After:

>     total W = _pkg_ (cores + _gpu_ + other) + _ram_ W
> #01  8.06 W =  6.70 ( 2.08 +  0.00 +  4.61) +  1.36 W
> 
> 1 sample taken over a period of 30.000 seconds
> 
> Name                               ID     CPU ms/s  User%  Deadlines (<2 ms, 2-5 ms)  Wakeups (Intr, Pkg idle)  GPU ms/s
> com.apple.Terminal                 293    402.97                                      236.31  42.75             0.00
>   plugin-container                 39164  354.22    96.81  172.74  1.13               193.09  18.83             0.00
>   firefox                          39163  43.67     56.50  1.47    4.17               42.75   23.66             0.00
>   Terminal                         694    5.37      87.92  0.00    0.00               0.37    0.23              0.00

I also measured with tools/power/rapl on my Linux desktop and the total processor+memory power dropped from 17.08 Watts to 10.47 Watts.

Nice work!

Comment 17

[Nicholas Nethercote [inactive]]

BTW, heycam's patch should probably be filed in a bug report that blocks this one, because it helps but doesn't completely fix the problem -- even with it we're still clearly worse than Chrome and Safari.

Comment 18

[Nicholas Nethercote [inactive]]

Alice, now that heycam's patches in bug 1203766 have landed, could you please try again on your machine and see how things look? (You might need to wait until tomorrow for the changes to make it into a Nightly build; not sure about that.) I expect it'll be better but still not ideal. Thank you.

Comment 19

[Alice0775 White]

(In reply to Nicholas Nethercote [:njn] from comment #18)
> Alice, now that heycam's patches in bug 1203766 have landed, could you
> please try again on your machine and see how things look? (You might need to
> wait until tomorrow for the changes to make it into a Nightly build; not
> sure about that.) I expect it'll be better but still not ideal. Thank you.


In Windows7, it is almost same. (as long as I observe the Task Manager)

https://hg.mozilla.org/mozilla-central/rev/11dc79e232110ba6de5179e46dfbda77b52a88c3
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:43.0) Gecko/20100101 Firefox/43.0 ID:20150918030202

Comment 20

[Gregory Pappas [:gregp]]

I think this is still a problem
https://share.firefox.dev/3MZsG8E

Comment 21

[Andrew McCreight [:mccr8]]

It looks like a lot of Stylo in that profile, not that I'm good at reading the profiler.

Comment 22

[Emilio Cobos Álvarez [:emilio]]

This is just bug 1381071

Comment 23

[Andrew McCreight [:mccr8]]

Thanks for taking a look, Emilio.

Comment 24

[Emilio Cobos Álvarez [:emilio]]

Sent a patch there, because I came up with an approach that is much simpler than what I tried back in the day.