1388179 - Excessive time spent in layout/style when clicking rightarrow on Facebook photo viewer

Status: NEW

(Core :: CSS Parsing and Computation, defect, P3)

Description

[Sean Stangl [:sstangl]]

The following recording is from clicking the "Right" arrow in the Facebook Photo viewer: https://perfht.ml/2vIO0LA

The DOMEvent of type "click" lasts about 104ms.

Of those 104ms, roughly 18% are spent just in mozilla::Dom::HTMLElementBinding::get_offsetWidth(), calling GetOffsetRect(), which seems to go off on a tangent calling nsCSSFrameConstructor::CreateNeededFrames().

The JS code that triggers this is the following:

> k.prototype.resize = function() {
>   "use strict";
>   if (this._body.style.width)
>     this._body.style.width='';
>   var l = this._wrap.offsetWidth - this._wrap.clientWidth;
>   if (l > 0)
>     c('Style').set(this._body, 'margin-right', -l + 'px');
>   return this;
> }

I'm not sure if there's anything that can be improved here, but that's the one hotspot that really stands out in the profile.

Comment 1

[Daniel Holbert [:dholbert]]

(In reply to Sean Stangl [:sstangl] from comment #0)
> Of those 104ms, roughly 18% are spent just in
> mozilla::Dom::HTMLElementBinding::get_offsetWidth(), calling
> GetOffsetRect(), which seems to go off on a tangent calling
> nsCSSFrameConstructor::CreateNeededFrames().

This tangent (CreateNeededFrames) is a normal result of a style or layout flush, FWIW.  And get_offsetWidth does flush layout.  So, this isn't especially surprising.

Occasionally we find bugs where we're needlessly *reconstructing* frames, but it doesn't seem like that's happening here...  Still, maybe room for optimization.

Comment 2

[Daniel Holbert [:dholbert]]

I'll take another look here to see if there's anything actionable...

Comment 3

[Daniel Holbert [:dholbert]]

I reprofiled, using rough STR from bug 1381383 (with an album of my own photos on Facebook), and current Nightly (on Linux64). 

Here's the full profile (content process 4 is the relevant one): https://perfht.ml/2k5wVDo
...zoomed to the click event: https://perfht.ml/2BRDe5r

Looks like the click DOMEvent handling is still long (122ms, which is still in the ballpark of 104ms noted in comment 0).  Here are the layout/style places we're spending time during that click handler:

HIGH LEVEL:
 - 10ms with "reflow" in the stack (longest being a 5.6ms reflow right after some frame construction)
 - 40ms with "style" in the stack
(I'm generalizing this bug to cover all of this layout/style time, for now, rather than just the single offsetWidth call that this bug was filed on, which may or may not be actionable.)


MORE GRANULAR: This breaks down into the following primary hot spots of ~continuous style or layout work:
 (A) 9.8ms answering a bunch of nsComputedDOMStyle queries from JS code: https://perfht.ml/2BTwMLd
       (note: 8ms of this is in calls to ResolveStyleFor: https://perfht.ml/2BRBaue )
 (B) 7.6ms restyle (light blue bar) which is mostly in nsCSSFrameConstructor::CreateNeededFrames: https://perfht.ml/2BTxEPY
 (C) 5.8ms reflow, right after that frame construction: https://perfht.ml/2BVcocY
 (D) 6.3ms restyle (light blue bar) which is mostly in mozilla::ElementRestyler::RestyleChildren: https://perfht.ml/2BSu2he
       (note: this is the "get_offsetWidth" call that originally spawned this bug)

Comment 4

[Daniel Holbert [:dholbert]]

Attachment: screenshot of Chrome's profiler results

I just profiled this once on Chrome 64 DevEdition (not entirely scientific, since I'm comparing just 1 Firefox measurement against just 1 Chrome measurement), and I got some useful results for comparison. I'm attaching a screenshot, which shows a high-level overview of the Chrome profile, including many of the function names noted below.

Firstly, comparing the full click event handler:
    81.32ms in Chrome
    122ms in Firefox
  (Chrome is clearly a good deal faster.)


Breaking down the click event handler:
1. JS function called "transitionHandler":
  - 14.99ms in Chrome
  - 30.8ms in Firefox: https://perfht.ml/2ka4cgW
   (This encapsulates the style work labeled as "A" in previous comment. Chrome's profiler shows 0.34ms "Restyle" here (whereas we spend nearly 10ms in ResolveStyle - not sure if that's reported differently in Chrome's profiler) and 0.92ms "Layout" (we spend 1.2ms).

2. JS Function called "fixButtonText" (mostly spent in "getPropertyValue")
  - 13.57ms in Chrome
  - 14.0ms in Firefox: https://perfht.ml/2k6S7cj
   (This encapsulates "B" and "C" restyle/reflow from previous comment. Chrome's profiler shows them spending similar times in restyle/reflow here -- their restyle is 1ms slower than ours, and their reflow is 1ms faster.)

3. JS function called "adjustScroller"
  - 6.55ms in Chrome
  - 12.2ms in Firefox: https://perfht.ml/2k6Zz7g
   This encapsulates the "D" restyle from previous comment.)
   Chrome's profiler shows this breaking down into 0.82ms of Recalculate Style and 2.31ms of Layout (with the rest of the time doing other stuff). Whereas we spend 6.3ms restyling and very little time (during "adjustScroller") doing any layout/reflow.

So (2) looks pretty comparable, but we have work to do on the others parts. Specifically these JS functions in Facebook's JS:
 (1) "transitionHandler" (which takes ~2x as long in Firefox vs. Chrome, with ResolveStyleFor being an obvious hot-spot in our code.
 (3) "adjustScroller" (which takes ~2x as long in Firefox vs. Chrome, with ElementRestyler::ComputeStyleChangeFor / RestyleChildren being an obvious hot-spot in our code.


emilio, perhaps you can take a look? Do you know if either of theese are likely to benefit from the proposed fixes on bug 1381071?

Comment 5

[Emilio Cobos Álvarez (:emilio)]

ElementRestyler is not stylo code, but the old style system. Any chance to grab a stylo profile?

Comment 6

[Daniel Holbert [:dholbert]]

Drat, you're right. I just assumed a fresh Nightly profile would be using stylo (as normally is the case), but it looks like I got randomly selected to have stylo-disabled, via a Shield study. I'll retest with Stylo enabled.

Comment 7

[Daniel Holbert [:dholbert]]

I'm reposting comment 4, in a stylo-enabled build.

Profile of full click event, in Firefox-stylo https://perfht.ml/2A2RmYc
The full click is 120ms in Firefox -- still a good bit slower than Chrome.  But now only 20ms have "style" in the stack (half as much as in my earlier accidentally-stylo-disabled test in comment 3)

Breaking down the click event handler into its main JS functions:
1. JS function called "transitionHandler":
  - 14.99ms in Chrome
  - 45.4ms in Firefox-stylo: https://perfht.ml/2nEUpnU
    ...but only 7ms of this has "style" in the stack (4.8ms of which is in nsComputedDOMStyle accessors)  There may be something we can optimize here, but even if we optimized style away entirely, we're still left with a measurement much slower than Chrome. I'll spin off a different bug to cover this.

2. JS Function called "fixButtonText" (mostly spent in "getPropertyValue")
  - 13.57ms in Chrome
  - 10.8ms in Firefox-stylo: https://perfht.ml/2nEZDjy
    (This includes 7ms in ServoRestyleManager::DoProcessPendingRestyles, and 3.6ms in Reflow)

3.  JS function called "adjustScroller"
  - 6.55ms in Chrome
  - 3.4ms in Firefox-stylo: https://perfht.ml/2nDZqwR

So I think to the extent that there's any layout/style stuff that can be optimized here (using Chrome's measurements as a baseline), it'd be the style stuff in part 1 (transitionHandler).  Retagging emilio to see if there's anything obviously optimizable there (since we spend 50% as much time in style code as Chrome spends running that entire function).  If it helps, here's a profile with STYLO_THREADS=1 (which disables parallelization but may make the profile more readable at the lower levels): https://perfht.ml/2nJEXaj

Comment 8

[Daniel Holbert [:dholbert]]

(In reply to Daniel Holbert [:dholbert] from comment #7)
> Breaking down the click event handler into its main JS functions:
> 1. JS function called "transitionHandler":
[...]
>  There may be something we can optimize here,
> but even if we optimized style away entirely, we're still left with a
> measurement much slower than Chrome. I'll spin off a different bug to cover
> this.

I filed bug 1424057 on the non-style-system slowness in this function.

Comment 9

[Emilio Cobos Álvarez (:emilio)]

I don't see anything terribly obvious there, it's a normal style flush.