1478999 - MozDropmarker is visible in Firefox window opening profiles

Status: RESOLVED FIXED

(Firefox :: General, defect, P3)

Description

[Florian Quèze [:florian]]

Here is a profile of opening many browser windows (keeping Cmd+n pressed for a little while), I was surprised to see "MozDropmarker" represent 7% of the total JS time in the profile: https://perfht.ml/2NQeu2O

Comment 1

[Brian Grinstead [:bgrins]]

On that profile I see MozXULElement at `chrome://global/content/customElements.js:839` - I assume 839 is supposed to be a line number but the file isn't that big: https://searchfox.org/mozilla-central/source/toolkit/content/customElements.js.

I guess the overhead here is constructing the class? MozDropmarker does almost nothing.

Comment 2

[Florian Quèze [:florian]]

That line number is indeed surprising.

When looking at the combined stacks too, it seems the time is mostly spent in mozilla::dom::Element::GetBindingURL asking servo to resolve styles.

From the discussions I had yesterday with :emilio in bug 1478675, it seems we pay that price whenever we access from JS code a DOM node that isn't visible (so hasn't been styled yet) but may have a binding attached to it (so we have to do CSS work to decide immediately if a binding needs to be attached before letting JS code access the node).

Comment 3

[Florian Quèze [:florian]]

(In reply to Brian Grinstead [:bgrins] from comment #1)
> On that profile I see MozXULElement at
> `chrome://global/content/customElements.js:839` - I assume 839 is supposed
> to be a line number but the file isn't that big:
> https://searchfox.org/mozilla-central/source/toolkit/content/customElements.
> js.

Markus, any idea of who could help with the incorrect line numbers here? Is it a profiler bug or a spidermonkey bug?

Comment 4

[Brian Grinstead [:bgrins]]

It would be helpful if you can confirm that the issue still exists with MozDropmarker's connectedCallback commented out: https://searchfox.org/mozilla-central/source/toolkit/content/widgets/general.js#39-46. I'm assuming it will since most of the time seems to be in MozXULElement, but MozXULElement only has a couple of static methods defined so I'm not sure what we could do here.

Comment 5

[Markus Stange [:mstange]]

(In reply to Florian Quèze [:florian] from comment #3)
> (In reply to Brian Grinstead [:bgrins] from comment #1)
> > On that profile I see MozXULElement at
> > `chrome://global/content/customElements.js:839` - I assume 839 is supposed
> > to be a line number but the file isn't that big:
> > https://searchfox.org/mozilla-central/source/toolkit/content/customElements.
> > js.
> 
> Markus, any idea of who could help with the incorrect line numbers here? Is
> it a profiler bug or a spidermonkey bug?

Spidermonkey bug, I'd say. The profiler just passes that string through unchanged. 
https://searchfox.org/mozilla-central/rev/d47c829065767b6f36d29303d650bffb7c4f94a3/js/src/vm/GeckoProfiler.cpp#291

Comment 6

[Florian Quèze [:florian]]

(In reply to Markus Stange [:mstange] from comment #5)
> (In reply to Florian Quèze [:florian] from comment #3)
> > (In reply to Brian Grinstead [:bgrins] from comment #1)
> > > On that profile I see MozXULElement at
> > > `chrome://global/content/customElements.js:839` - I assume 839 is supposed
> > > to be a line number but the file isn't that big:
> > > https://searchfox.org/mozilla-central/source/toolkit/content/customElements.
> > > js.
> > 
> > Markus, any idea of who could help with the incorrect line numbers here? Is
> > it a profiler bug or a spidermonkey bug?
> 
> Spidermonkey bug, I'd say. The profiler just passes that string through
> unchanged. 
> https://searchfox.org/mozilla-central/rev/
> d47c829065767b6f36d29303d650bffb7c4f94a3/js/src/vm/GeckoProfiler.cpp#291

Nicolas, could you please forward the needinfo to someone who could help with incorrect line numbers in JS stacks?

Comment 7

[Florian Quèze [:florian]]

(In reply to Brian Grinstead [:bgrins] from comment #4)
> It would be helpful if you can confirm that the issue still exists with
> MozDropmarker's connectedCallback commented out:
> https://searchfox.org/mozilla-central/source/toolkit/content/widgets/general.
> js#39-46. I'm assuming it will since most of the time seems to be in
> MozXULElement, but MozXULElement only has a couple of static methods defined
> so I'm not sure what we could do here.

As I wrote in comment 2, I don't think the cost is in JS code being executed, but rather in accessing the DOM node too early.

Comment 8

[Nicolas B. Pierron [:nbp]]

Some incorrect line numbers are expected in cases where we have "new Function" or eval, but I cannot spot any in the file.

One experiment would be to add a printf at the end of JSScript::fullyInitFromEmitter which dumps the filename and line number and see if you get any inconsistency like reported by the profiler, and if so use rr to walk your way back from where the line number comes from.

Comment 9

[Sam Foster [:sfoster] (he/him)]

Triage: moving to backlog while investigation is underway.

Comment 10

[Jason Orendorff [:jorendorff]]

Confirmed, that's a JS engine bug. JS class default constructors always have the wrong line number.

(This is why the two line numbers in the profile are the same. They're both derived-class constructors for JS classes that don't have an explicit `constructor()` method. As it happens, that line number is the line number of DefaultDerivedClassConstructor in $OBJDIR/js/src/selfhosted.js; it corresponds to nothing in the source tree.)

I only got this because I coincidentally found out about a related bug (same root cause) yesterday. Bug 1473272.

This bug is not a dup of that one, though I hope this helps. The correct stack is what you see if you switch to Combined Stacks:

    MozDropMarker (default constructor)
     -> MozXULElement (default constructor)
         -> XULElement constructor
             -> mozilla::dom::Element::WrapObject
                 -> mozilla::dom::Element::GetBindingURL
                     -> mozilla::ServoStyleSet::ResolveStyleLazilyInternal
   
I can't currently ni?florian. bgrins?

Comment 11

[Brian Grinstead [:bgrins]]

(In reply to Jason Orendorff [:jorendorff] from comment #10)
> Confirmed, that's a JS engine bug. JS class default constructors always have
> the wrong line number.
> 
> (This is why the two line numbers in the profile are the same. They're both
> derived-class constructors for JS classes that don't have an explicit
> `constructor()` method. As it happens, that line number is the line number
> of DefaultDerivedClassConstructor in $OBJDIR/js/src/selfhosted.js; it
> corresponds to nothing in the source tree.)
> 
> I only got this because I coincidentally found out about a related bug (same
> root cause) yesterday. Bug 1473272.

Alright, thanks for the info. Jason, will Bug 1473272 fix the wrong line number issue we are seeing in this case, or should we have a new bug to track this?

> This bug is not a dup of that one, though I hope this helps. The correct
> stack is what you see if you switch to Combined Stacks:
> 
>     MozDropMarker (default constructor)
>      -> MozXULElement (default constructor)
>          -> XULElement constructor
>              -> mozilla::dom::Element::WrapObject
>                  -> mozilla::dom::Element::GetBindingURL
>                      -> mozilla::ServoStyleSet::ResolveStyleLazilyInternal
>    
> I can't currently ni?florian. bgrins?

Alright yeah, that stack matches what we expected (needing to resolve style to see if a XBL binding is attached). Emilio, I wonder if we could skip calls to resolve styles for elements we know don't have XBL bindings attached? Either a whitelist of tags that do (which we could pretty easily derive from https://bgrins.github.io/xbl-analysis/tree/), or a blacklist of tags that don't (i.e. "dropmarker" in this case).

Comment 12

[Emilio Cobos Álvarez (:emilio)]

Yeah, we could change the condition here with an early-out:

  https://searchfox.org/mozilla-central/rev/2466b82b729765fb0a3ab62f812c1a96a7362478/dom/base/Element.cpp#542

Just like we do for non-XUL, non-<object>, non-<embed> things, we could do for non-XUL-foo things.

Ideally we'd get rid of that hack completely but... :)

Comment 13

[Jason Orendorff [:jorendorff]]

(In reply to Brian Grinstead [:bgrins] from comment #11)
> Alright, thanks for the info. Jason, will Bug 1473272 fix the wrong line
> number issue we are seeing in this case, or should we have a new bug to
> track this?

Looks like that patch will fix it.

Comment 14

[Brian Grinstead [:bgrins]]

(In reply to Emilio Cobos Álvarez (:emilio) from comment #12)
> Yeah, we could change the condition here with an early-out:
> 
>  
> https://searchfox.org/mozilla-central/rev/
> 2466b82b729765fb0a3ab62f812c1a96a7362478/dom/base/Element.cpp#542
> 
> Just like we do for non-XUL, non-<object>, non-<embed> things, we could do
> for non-XUL-foo things.
> 
> Ideally we'd get rid of that hack completely but... :)

One day :)

Comment 15

[Brian Grinstead [:bgrins]]

I'll try making the change in Comment 12 and see if it helps

Comment 16

[Brian Grinstead [:bgrins]]

Attachment: Bug 1478999 - Don't check for -moz-binding on dropmarker to avoid getting computed style in GetBindingURL;r=emilio

This is slow to do when the element isn't visible, and we know it
won't have a XBL binding anyway, since it's a Custom Element.

Comment 17

[Brian Grinstead [:bgrins]]

Without the patch applied when holding down ctrl+n I also see around 8% running time in MozDropmarker: https://perf-html.io/public/cf35c68b6c0bca704fe90906d943c1f2f2814a1c/calltree/?globalTrackOrder=0-1-2-3-4-5&hiddenGlobalTracks=1-2-3-4-5&hiddenLocalTracksByPid=33473-0&implementation=js&localTrackOrderByPid=33473-0~&search=dropmarker&thread=0&v=3

With the patch applied when holding down ctrl+n it drops down to 0%: https://perf-html.io/public/a2826992525d7755a4b04008e7f1e6a9d1af8060/calltree/?globalTrackOrder=0-1-2-3-4-5&hiddenGlobalTracks=1-2-3-4-5&hiddenLocalTracksByPid=35453-0&implementation=js&localTrackOrderByPid=35453-0~&search=mozdro&thread=0&v=3

Comment 18

[Brian Grinstead [:bgrins]]

Especially as we make more progress on removing bindings I could see flipping this on its head and only attempting to compute style for a whitelisted set of tag names. For now this seems to be a big improvement.

Comment 19

[Emilio Cobos Álvarez (:emilio)]

Comment on attachment 9001725 [details]
Bug 1478999 - Don't check for -moz-binding on dropmarker to avoid getting computed style in GetBindingURL;r=emilio

Emilio Cobos Álvarez (:emilio) has approved the revision.

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/7a70031ea18a
Don't check for -moz-binding on dropmarker to avoid getting computed style in GetBindingURL;r=emilio

Comment 21

[Daniel Varga [:dvarga]]

https://hg.mozilla.org/mozilla-central/rev/7a70031ea18a