Closed Bug 1478999 Opened Last year Closed Last year

MozDropmarker is visible in Firefox window opening profiles

Categories

(Firefox :: General, defect, P3)

defect

Tracking

()

RESOLVED FIXED
Firefox 63
Tracking Status
firefox63 --- fixed

People

(Reporter: florian, Assigned: bgrins)

References

Details

(Whiteboard: [fxperf])

Attachments

(1 file)

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
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.
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).
(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?
Flags: needinfo?(mstange)
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.
(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
Flags: needinfo?(mstange)
(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?
Flags: needinfo?(nicolas.b.pierron)
(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.
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.
Flags: needinfo?(nicolas.b.pierron) → needinfo?(jorendorff)
Triage: moving to backlog while investigation is underway.
Priority: -- → P3
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?
Flags: needinfo?(jorendorff) → needinfo?(bgrinstead)
(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).
Flags: needinfo?(jorendorff)
Flags: needinfo?(emilio)
See Also: → 1473272
Flags: needinfo?(bgrinstead)
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... :)
Flags: needinfo?(emilio)
(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.
Flags: needinfo?(jorendorff)
(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 :)
I'll try making the change in Comment 12 and see if it helps
Assignee: nobody → bgrinstead
Status: NEW → ASSIGNED
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.
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 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.
Attachment #9001725 - Flags: review+
Blocks: 1484285
Pushed by bgrinstead@mozilla.com:
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
https://hg.mozilla.org/mozilla-central/rev/7a70031ea18a
Status: ASSIGNED → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Target Milestone: --- → Firefox 63
You need to log in before you can comment on or make changes to this bug.