Closed Bug 1451340 Opened 6 years ago Closed 6 years ago

3.25% damp (windows7-32) regression on push e220521c6ff6 (Tue Apr 3 2018)

Categories

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

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla61
Tracking Status
firefox-esr52 --- unaffected
firefox59 --- unaffected
firefox60 --- unaffected
firefox61 + fixed

People

(Reporter: igoldan, Assigned: bgrins)

References

Details

(Keywords: perf, regression, talos-regression)

Attachments

(1 file)

Talos has detected a Firefox performance regression from push:

https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=8f3d33f7c72babbf232f1938e982d4dd5f54f142&tochange=e220521c6ff6ff9a45e19b3917ba95e678fd9932

As author of one of the patches included in that push, we need your help to address this regression.

Regressions:

  3%  damp windows7-32 pgo e10s stylo     70.18 -> 72.47


You can find links to graphs and comparison views for each of the above tests at: https://treeherder.mozilla.org/perf.html#/alerts?id=12476

On the page above you can see an alert for each affected platform as well as a link to a graph showing the history of scores for this test. There is also a link to a treeherder page showing the Talos jobs in a pushlog format.

To learn more about the regressing test(s), please see: https://wiki.mozilla.org/Buildbot/Talos/Tests

For information on reproducing and debugging the regression, either on try or locally, see: https://wiki.mozilla.org/Buildbot/Talos/Running

*** Please let us know your plans within 3 business days, or the offending patch(es) will be backed out! ***

Our wiki page outlines the common responses and expectations: https://wiki.mozilla.org/Buildbot/Talos/RegressionBugsHandling
Component: Untriaged → DOM: Core & HTML
Product: Firefox → Core
:bgrins Can you please look over this perf regression?
Flags: needinfo?(bgrinstead)
(In reply to Ionuț Goldan [:igoldan], Performance Sheriffing from comment #1)
> :bgrins Can you please look over this perf regression?

Sure, I'll see if adding a list of tag names that can't be Custom Elements makes a difference
Assignee: nobody → bgrinstead
Status: NEW → ASSIGNED
Flags: needinfo?(bgrinstead)
(In reply to Ionuț Goldan [:igoldan], Performance Sheriffing from comment #0)
>   3%  damp windows7-32 pgo e10s stylo     70.18 -> 72.47
> 
> 
> You can find links to graphs and comparison views for each of the above
> tests at: https://treeherder.mozilla.org/perf.html#/alerts?id=12476

This alert is surprising. A 3% regression is reported, this looks significant.
But when you look at subtests:
https://treeherder.mozilla.org/perf.html#/comparesubtest?originalProject=autoland&originalRevision=e220521c6ff6ff9a45e19b3917ba95e678fd9932&newProject=autoland&newRevision=1fb1569b61d292785497c3f662b8a387c638695a&originalSignature=389a5b1ef37772bad22611e4d6237fffea35c9cb&newSignature=389a5b1ef37772bad22611e4d6237fffea35c9cb&showOnlyImportant=1&framework=1

The regression isn't so obvious.
We may have regression on:
  cold.inspector.open by 2.95%
  inspector.mutations by 5.25%
The rest looks like noise and I hope the special average computation talos is using isn't emphasising the noise of complicated.styleeditor.reload.settle and simple.netmonitor.exportHar.

Was the alert only on Windows 7?

(In reply to Brian Grinstead [:bgrins] from comment #3)
> With the blacklist I see -1.40% on win7-32 damp, but it's low confidence:
> https://treeherder.mozilla.org/perf.html#/
> compare?originalProject=try&originalRevision=10dfb24dd66e7509c3c4a6bf5186d4e9
> f4f0b8ae&newProject=try&newRevision=ad525e966d2c6a87eaee8e4e2946f772d57d4b18&
> framework=1&filter=damp.

And in this try run, you do not seem to recover from any regression on these two tests.

When looking a the trend for cold.inspector.open, the regression isn't so obvious:
https://treeherder.mozilla.org/perf.html#/graphs?series=mozilla-central,1654655,1,1&highlightedRevisions=e220521c6ff6&zoom=1522497031002.7903,1522879360000,727.4390013677546,805.122795501492
While it look more around 770/780 after this patch, it has a lot less noise...

The regression may be more visible for inspector.mutations:
https://treeherder.mozilla.org/perf.html#/graphs?series=mozilla-central,1654704,1,1&highlightedRevisions=e220521c6ff6&zoom=1522444081940.3022,1522879360000,966.1672756466526,1095.0062269575142

If you have any idea on how to improve DAMP/talos about all that...
(In reply to Alexandre Poirot [:ochameau] from comment #4)
> Was the alert only on Windows 7?

The regression happens also on Windows 10 and OS X.
OK, when I comment out the early return in IsCustomElementName entirely I see:

windows10-64 -2.36% 4.34 (med)
windows7-32 -2.66% 3.08 (med)

https://treeherder.mozilla.org/perf.html#/compare?originalProject=try&originalRevision=7857baf1fca4be563a2a7716f4a647b91639388f&newProject=try&newRevision=8a7e056c1d155e4219f458e2ddef14b424a80861&framework=1&filter=damp

Scanning the subtests, this appears to be due to large high confidence improvements to damp custom.webconsole.close.DAMP custom.webconsole.reload.DAMP. Which is interesting since it's not running in a XUL doc.
(In reply to Brian Grinstead [:bgrins] from comment #6)
> Scanning the subtests, this appears to be due to large high confidence
> improvements to damp custom.webconsole.close.DAMP
> custom.webconsole.reload.DAMP. Which is interesting since it's not running
> in a XUL doc.

Oh right I missed by how much (+4200%!!) this test increased.
I don't have words to say how surprising this is!

Here is a profile of DAMP. It may help you as we see very slow function calls related to bindings:
  https://perfht.ml/2GGsglC
  nsXBLBinding::UnbindAnonymousContent is taking most of computation time during custom.webconsole.close.
Which seems to come from this JS call:
  https://searchfox.org/mozilla-central/source/devtools/client/webconsole/jsterm.js#1816
Huh, the only XBL anon content I think we'd use in this html doc is for the scrollbar. And I don't know why making it a valid custom element name would change the unbind time, but let me try adding it to the blacklist.
Easy way to reproduce the slow close:

./mach run --setpref devtools.toolbox.selectedTool=webconsole --devtools 'testing/talos/talos/tests/devtools/addon/content/pages/custom/console/index.html?sync=250&stream=250&async=250'
Apparently that DAMP page generates 27036 anon children (xul:scrollbarbutton, xul:slider, and xul:thumb) and 4506 scrollbars (generated by running this in the Browser Toolbox on the previous mach command when targeting webconsole.html):

```
var anonElements = [];
var walker = Cc["@mozilla.org/inspector/deep-tree-walker;1"].
             createInstance(Ci.inIDeepTreeWalker);
walker.showAnonymousContent = true;
walker.showSubDocuments = false;
walker.showDocumentsAsNodes = false;
walker.init(document.documentElement, NodeFilter.SHOW_ELEMENT);


while (walker.nextNode()) {
  var bindingParent = document.getBindingParent(walker.currentNode);
  if (bindingParent && document.getAnonymousNodes(bindingParent)) {
    anonElements.push(walker.currentNode);
  }
}
anonElements;
```
OK steps to reproduce my testing locally:

* Replace `this.hud.outputNode.innerHTML = "";` from Comment 7 with `let n = Date.now(); this.hud.outputNode.innerHTML = ""; console.log("Took " + (Date.now() - n) + "ms to close console");`
* ./mach run --setpref devtools.toolbox.selectedTool=webconsole 'testing/talos/talos/tests/devtools/addon/content/pages/custom/console/index.html?sync=250&stream=250&async=250'
* Open console and wait for rendering to finish
* Close console

With no changes I get: console.log: "Took 17965ms to close console"
If I return false on `scrollbar`, `scrollbarbutton`, `slider`, `thumb` I get: "Took 364ms to close console"
Looks like the reason we have so many scrollbars in the console is that we have `.tree { overflow: auto; }` and that gets used for every logged object that can be expanded.
Comment on attachment 8965419 [details]
Bug 1451340 - Don't attempt to RegisterUnresolvedElement for native anonymous content;

https://reviewboard.mozilla.org/r/234172/#review239804
Attachment #8965419 - Flags: review?(bugs) → review+
Pushed by bgrinstead@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/4a148fbce5fc
Don't attempt to RegisterUnresolvedElement for native anonymous content;r=smaug
https://hg.mozilla.org/mozilla-central/rev/4a148fbce5fc
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
== Change summary for alert #12549 (as of Fri, 06 Apr 2018 02:16:59 GMT) ==

Improvements:

  5%  damp linux64 opt e10s stylo     64.23 -> 60.84
  5%  damp windows10-64 opt e10s stylo75.48 -> 71.95
  3%  damp windows7-32 opt e10s stylo 83.25 -> 80.36
  3%  damp windows10-64 pgo e10s stylo69.94 -> 67.77

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=12549
You need to log in before you can comment on or make changes to this bug.