Closed Bug 880611 (australis-ts) Opened 11 years ago Closed 11 years ago

Investigate 3% regression on ts_paint on UX

Categories

(Firefox :: Theme, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
Firefox 28

People

(Reporter: MattN, Unassigned)

References

Details

(Keywords: meta, perf)

Attachments

(1 file, 1 obsolete file)

Commenting out "CustomizableUIInternal.initialize()" at the bottom of CustomizableUI.jsm brought performance back to m-c values or better on Windows  XP & 7 non-PGO. 

Using the Gecko profiler with only JS showing, ranked onReadyStateChange() of toolbar.xml near the top of the running time (~1.5%).
The stack is:
onReadyStateChange() @ toolbar.xml:28
=> _init @ toolbar.xml:38
   => registerToolbar @ CustomizableUI.jsm:1745
   => <Anonymous> @ CustomizableUI.jsm:1
Bumping these to M8, since M7 finished yesterday.
Whiteboard: [Australis:M7] → [Australis:M8]
Depends on: 885452
No longer depends on: 885452
We use CustomizbleUI to build the toolbars on startup, but this requires we load CustomizableUI (and thus CustomizableWidgets.jsm and CustomizeMode.jsm).

Can we have a smaller footprint of code that just takes the stored configuration and applies that to the toolbars (which doesn't carry with it these three modules)?
I suspect that the Talos profile is going to be having migrations run due to a lower browser.migration.version pref value and because of a lack of browser.uiCustomization.state.
(In reply to Jared Wein [:jaws] from comment #3)
> We use CustomizbleUI to build the toolbars on startup, but this requires we
> load CustomizableUI (and thus CustomizableWidgets.jsm and CustomizeMode.jsm).
> 
> Can we have a smaller footprint of code that just takes the stored
> configuration and applies that to the toolbars (which doesn't carry with it
> these three modules)?

CustomizeMode.jsm shouldn't be loaded - if it is, its a bug.

And CustomizableWidgets.jsm needs to be loaded in most cases anyway, because toolbars usually contain widgets from there.
I whipped up a patch to try building areas with document fragments instead of touching the DOM directly:

https://tbpl.mozilla.org/?tree=Try&rev=dc66705cd70e

Let's hope it's this simple.
(In reply to Blair McBride [:Unfocused] from comment #5)
> (In reply to Jared Wein [:jaws] from comment #3)
> > We use CustomizbleUI to build the toolbars on startup, but this requires we
> > load CustomizableUI (and thus CustomizableWidgets.jsm and CustomizeMode.jsm).
> > 
> > Can we have a smaller footprint of code that just takes the stored
> > configuration and applies that to the toolbars (which doesn't carry with it
> > these three modules)?
> 
> CustomizeMode.jsm shouldn't be loaded - if it is, its a bug.
> 
> And CustomizableWidgets.jsm needs to be loaded in most cases anyway, because
> toolbars usually contain widgets from there.

My anecdotal evidence is that the Browser Debugger only lists JSMs that have been loaded. For example, if I launch the browser and open the Browser Debugger I won't see DeveloperToolbar.jsm as a source file, but I do see all three of the customize JSMs without entering customization mode or opening the menu panel.
(In reply to Jared Wein [:jaws] from comment #7)
> (In reply to Blair McBride [:Unfocused] from comment #5)
> > (In reply to Jared Wein [:jaws] from comment #3)
> > > We use CustomizbleUI to build the toolbars on startup, but this requires we
> > > load CustomizableUI (and thus CustomizableWidgets.jsm and CustomizeMode.jsm).
> > > 
> > > Can we have a smaller footprint of code that just takes the stored
> > > configuration and applies that to the toolbars (which doesn't carry with it
> > > these three modules)?
> > 
> > CustomizeMode.jsm shouldn't be loaded - if it is, its a bug.
> > 
> > And CustomizableWidgets.jsm needs to be loaded in most cases anyway, because
> > toolbars usually contain widgets from there.
> 
> My anecdotal evidence is that the Browser Debugger only lists JSMs that have
> been loaded. For example, if I launch the browser and open the Browser
> Debugger I won't see DeveloperToolbar.jsm as a source file, but I do see all
> three of the customize JSMs without entering customization mode or opening
> the menu panel.

To add to that, keeping the Browser Debugger open and then opening the Developer Toolkit, all of a sudden DeveloperToolbar.jsm is available as a source and you can see that new sources are appearing in the sidebar.
(In reply to Mike Conley (:mconley) from comment #6)
> I whipped up a patch to try building areas with document fragments instead
> of touching the DOM directly:
> 
> https://tbpl.mozilla.org/?tree=Try&rev=dc66705cd70e
> 
> Let's hope it's this simple.

Unfortunately that consistently slower across XP and Win7 :(
That was unexpected. :/ Ok, let me try something else...
Ok, new push - this time, I've removed the buildArea operation for the toolbars - let's see how much buildArea contributes to the problem:

https://tbpl.mozilla.org/?tree=Try&rev=df4ef8b53316
Ok, it looks like buildArea is contributing a significant amount (maybe even all) to the regression. That's somewhat encouraging. I'll see what else we can tighten up in there.
So I poked at this today, and I've made some progress. I set up ts_paint to run locally on my Ubuntu box, and did some bisection.

I eventually found out that one of the most expensive things we did was use idToSelector in findWidgetInWindow (towards the bottom, querying the toolbox palettes for the node). idToSelector is *crazy expensive*, and it looks like toolbox.getElementsByAttribute("id", id) is the faster route.

Here is some data...

At 10 cycles of the ts_paint test on my Ubuntu box, here's what I got:

m-c             :  831.30ms
UX              :  873.00ms
no idToSelector :  840.10ms

I've pushed a patch to try: https://tbpl.mozilla.org/?tree=Try&rev=0804d83ed52b
Results on that try build are very encouraging.

I've filed bug 885926 to switch to getElementsByAttribute for palette queries.
Depends on: 885926
Whiteboard: [Australis:M8] → [Australis:M8][Australis:P1]
I may have broken out the champagne too soon - my patch had a bug where I was using element.getElementsByAttribute("id", aId), for a node instead of element.getElementsByAttribute("id", aId)[0]. Kinda makes all the difference, and now the regression is back. :/

Investigation continuing...
Windows improved a lot after the end of the previous graph on a merge cset. Here are some updated links:

WinXP med/max
http://graphs.mozilla.org/graph.html#tests=[[226,94,37],[226,137,37]]&sel=none&displayrange=30&datatype=running
http://graphs.mozilla.org/graph.html#tests=[[227,94,37],[227,137,37]]&sel=none&displayrange=30&datatype=running
(+/-  7%)

Win7 med/max
http://graphs.mozilla.org/graph.html#tests=[[226,94,25],[226,137,25]]&sel=none&displayrange=30&datatype=running
http://graphs.mozilla.org/graph.html#tests=[[227,94,25],[227,137,25]]&sel=none&displayrange=30&datatype=running
( --- 0)

Linux also saw some improvement, but still hovers in the +/- 15-16% regression range, which isn't great.
Summary: Investigate up to 25% regression on tspaint_places_generated_med/max on UX → Investigate up to 16% regression on tspaint_places_generated_med/max on UX
The patch for bug 873066 briefly fixed the XP regression, fwiw, and then things got worse again when it got backed out. Might be interesting to figure out what that patch does that speeds things up...
Regarding Linux, I am concerned it might be at least partially tabs/drawing-related. It's hard to be sure, but it *seems* that landing http://hg.mozilla.org/projects/ux/rev/6a1067f3c251 (bug 879595) made things slightly worse. It's been hard to isolate what's going on there in terms of the customization code influencing the talos. Mike and I have been poking at this continuously for a day or two now, without much progress.
Try push which I hope will scrape us at least a bit of a win: https://tbpl.mozilla.org/?tree=Try&rev=73d9d486abc5
(In reply to :Gijs Kruitbosch from comment #19)
> Try push which I hope will scrape us at least a bit of a win:
> https://tbpl.mozilla.org/?tree=Try&rev=73d9d486abc5

This doesn't seem to have helped at all, if anything it's worse. :-\
Amazingly, I wasn't able to get a profile off of an m-c build without the whole thing crashing. I had to use the stock Firefox in my Ubuntu distro, which happened to be 20.0.

So here's the start-up profile:

http://people.mozilla.com/~bgirard/cleopatra/#report=d2070688e837dfd7355bec9ded4f207a905d3e0c
Some bisecting of missing talos results:
A) eda465a0ed17 - First UX commit - UX Branding
   https://tbpl.mozilla.org/?tree=Try&rev=9768cea2e68a

B) 7d9922f790c4	Bug 823176 - Australis tabs styling for Linux
   https://tbpl.mozilla.org/?tree=Try&rev=b82a091fd86c

C) f7cb839f3bfc	Bug 770135 - New PanelUI and toolbar customization - Milestone 1
   https://tbpl.mozilla.org/?tree=Try&rev=6be9e8788c66

D) a84599943699	Bug 855229 - Adjust focus-rect on tabs for Australis
   https://tbpl.mozilla.org/?tree=Try&rev=8f6124393d7f

E) 8bf747097b31 Bug 685059 - Remove empty placeholder icon in tabs when a page has no…
   https://tbpl.mozilla.org/?tree=Try&rev=56148c34835d

F) f4002b4651c9 Bug 834284 - Lightweight theme support for Australis tabs on GTK Linux
   https://tbpl.mozilla.org/?tree=Try&rev=f9231332c09e
(In reply to Matthew N. [:MattN] from comment #23)
> Some bisecting of missing talos results:
> A) eda465a0ed17 - First UX commit - UX Branding
>    https://tbpl.mozilla.org/?tree=Try&rev=9768cea2e68a

So this has med/max results around 620 on Linux64 (broken on Linux32 because of conf changes). Current trunk does 580, but trunk at the earliest known point on that graph (April 11th) was doing 540. Funnily enough *almost every* try push at the time did 50-100ms worse than ordinary Firefox:

http://graphs.mozilla.org/graph.html#tests=[[226,113,33],[226,113,35],[226,1,33],[226,1,35]]&sel=none&displayrange=90&datatype=running

So it seems like try pushes are somehow fundamentally worse off than ordinary builds, for no reason that I can see.

> B) 7d9922f790c4	Bug 823176 - Australis tabs styling for Linux
>    https://tbpl.mozilla.org/?tree=Try&rev=b82a091fd86c
This didn't seem to have an impact.


> C) f7cb839f3bfc	Bug 770135 - New PanelUI and toolbar customization -
> Milestone 1
>    https://tbpl.mozilla.org/?tree=Try&rev=6be9e8788c66

This regresses with about 30-40ms compared to the first try push.

> 
> D) a84599943699	Bug 855229 - Adjust focus-rect on tabs for Australis
>    https://tbpl.mozilla.org/?tree=Try&rev=8f6124393d7f

And at this point we've regressed another 50-60ms.
(In reply to :Gijs Kruitbosch from comment #24)
> (In reply to Matthew N. [:MattN] from comment #23)
> > Some bisecting of missing talos results:
> > A) eda465a0ed17 - First UX commit - UX Branding
> >    https://tbpl.mozilla.org/?tree=Try&rev=9768cea2e68a
> 
> So this has med/max results around 620 on Linux64 (broken on Linux32 because
> of conf changes). Current trunk does 580, but trunk at the earliest known
> point on that graph (April 11th) was doing 540. Funnily enough *almost
> every* try push at the time did 50-100ms worse than ordinary Firefox:
> 
> http://graphs.mozilla.org/graph.html#tests=[[226,113,33],[226,113,35],[226,1,
> 33],[226,1,35]]&sel=none&displayrange=90&datatype=running
> 
> So it seems like try pushes are somehow fundamentally worse off than
> ordinary builds, for no reason that I can see.

That link was comparing PGO to non-PGO so that's why there was a big gap. This is a more accurate link for non-PGO:

http://graphs.mozilla.org/graph.html#tests=[[226,94,33],[226,137,33],[226,94,35],[226,137,35]]&sel=none&displayrange=7&datatype=running
Quick summary of a couple things from today's meeting:

* With already-landed fixes, this regression is now Linux-only. Windows and OS X should be ok.

* The graph link in comment 24 is bogus because it's comparing Try-NonPGO with Firefox-WithPGO. MattN's link in comment 25 is correct.

* That link shows a ~%14 regression, from 667ms --> 760ms (32bit Ubuntu), 626ms --> 716ms (64bit Ubuntu).

* MattN is going to continue bisecting from comment 24 (to find a tighter range fro the regressions seen in B-->C and C-->D), Jared's going to try some blind attempts to try identifying potential regression-causing things with XUL bits, Gijs is looking at the same with PanelUI.
Attached patch Hide the panel by default (obsolete) — Splinter Review
This gains us another tiny bit. I quickly checked our tests, those pass. I applied this on top of my patch in bug 888800 but I'm fairly sure it should apply cleanly on tip as well.
Attachment #770425 - Flags: review?(mnoorenberghe+bmo)
Depends on: 889597
Attachment #770425 - Attachment is obsolete: true
Attachment #770425 - Flags: review?(mnoorenberghe+bmo)
(In reply to Matthew N. [:MattN] from comment #28)
> More bisection between B and D:
> https://docs.google.com/spreadsheet/
> ccc?key=0Asj8iLTl0K0UdDcxemJEWVVXWTlKek1wR09iS2FsOXc&usp=sharing

So the landing of bug 888800 (default placements should be, uhh, the default - thanks for pushing us to fix this, gavin!) gained us quite a bit on Linux, and maybe a bit on OS X / Win7 / XP.

Then the landing of bug 889597 (panelUI hiding - thanks for this idea, jaws!) gained us everything we needed on Linux, a bit on XP/7, and seems to have regressed OS X? But then again, OS X has a boatload of variance. If you look at the actual runs of this cset (I retriggered 5 times):

http://graphs.mozilla.org/graph.html#tests=[[227,59,22],[227,1,22]]&sel=1372812899713.2556,1372862260072&displayrange=7&datatype=running

There's anything between 1020 (+5% on the previous cset) and 973 (par). So, I have no idea how we're doing there. :-|

Whatever the case, XP is still slightly (30ms / 540 ~= 6%) regressed (using the numbers of ttaubert's merge, because we haven't merged the cset at the top of the spreadsheet yet - jaws was going to do so because he knows some of the patches in there that will be tricky to merge correctly). Markus Stange is helping us out by doing gecko profiler runs on talos so we can see where we're spending time. More info when those builds finish.
Depends on: 890105
Progress! See row 7 of the spreadsheet:

https://docs.google.com/a/mozilla.com/spreadsheet/ccc?key=0Asj8iLTl0K0UdDcxemJEWVVXWTlKek1wR09iS2FsOXc#gid=0
Summary: Investigate up to 16% regression on tspaint_places_generated_med/max on UX → Investigate up to 7% regression on tspaint_places_generated_med/max on UX
Here are two profiles mstange did for us:

mc: http://tests.themasta.com/cleopatra/?report=3b398c05dca68649c45c8c4d3fd20498f108e4f0
ux: http://tests.themasta.com/cleopatra/?report=8a7f7e8c5918e3e1e112944cb74d2035e4145f71

The first is from https://tbpl.mozilla.org/php/getParsedLog.php?id=24882229&tree=Try which reported a value of 583.37 and the second is from https://tbpl.mozilla.org/php/getParsedLog.php?id=24895428&tree=Try which reported a value of 621.47 (6.5% more).

These are the results of 20 combined runs.

He further analyzed:

nsEventDispatcher::Dispatch increases from 557 to 676 (+119). It comes from calls to these three (new) functions:
47ms from onReadyStateChange() @ toolbar.xml:285
38ms from onReadyStateChange() @ toolbar.xml:28
20ms from <Anonymous>() @ panelUI.js:29

Another 92ms are from ClientMarginHitTestPoint, which isn't called in the mozilla-central profile at all. Could that be caused by different chromemargin handling?

82ms are due to new bindings (don't know which one), more CSS code, and from loading and decoding more images
(In reply to :Gijs Kruitbosch from comment #31)
> 82ms are due to… and from loading and decoding more images

If necessary we could look into using a sprite sheet for tab images. If I'm understanding the profile properly, that could only save a few milliseconds though.
Depends on: 890476
Depends on: 891104
Updating summary for clarification, per discussion with MattN...

Bug 889758 and bug 880611 overlap a bit, involving flavors of window painting regressions.

tpaint is effectively a subset of ts_paint, in that both are measuring time to paint a new window, but ts_paint includes app startup time as well. Any tpaint regression should should up in ts_paint, but the reverse is not always true.

EG: currently on XP-nonPGO, there is a ~19ms regression in tpaint, and a ~27ms regression in ts_paint (plain). [ts_paint also has "medium" and "max" variations, which I'm ignoring for the moment.] These numbers imply that there's actually a common ~19ms regression across both, and an additional 8ms (27 - 19) regression in startup. Or that 8ms might be in the noise now.

Using _this_ bug for tracking ts_paint, and the other bug for tracking the difference specific to tpaint.
Summary: Investigate up to 7% regression on tspaint_places_generated_med/max on UX → Investigate 5% regression on ts_paint on UX
Depends on: 892809
Depends on: 893682
Depends on: 894099
Keywords: meta
Assignee: mnoorenberghe+bmo → nobody
Depends on: 897260
This is now down to ~3% worst case on XP PGO ts_paint, medium, & max.
Summary: Investigate 5% regression on ts_paint on UX → Investigate 3% regression on ts_paint on UX
Depends on: 899587
No longer depends on: 899587
Depends on: australis-tpaint
Depends on: 901016
No longer depends on: 902924
Alias: australis-ts
Depends on: 904924
Depends on: 910283
Vladan has informed me that there's still ~5ms or so of ts_paint regression that is not caused by TabsInTitlebar or CustomizableUI.

However, he thinks it's not worth blocking Australis on this for such a small regression, and thinks we can lift this as a blocker. In exchange, he's asked me to help him with some cold-start perf work he'll be cranking out soon.
Whiteboard: [Australis:M8][Australis:P1]
All of the the dependencies have been fixed and the following decision was made[1]:

"Windows XP (+1.0% Non PGO, +2.0% PGO)
    The performance team has expressed that they are not concerned about this regression."

[1] https://wiki.mozilla.org/Firefox/Australis/Expected_talos_changes#ts_paint
Status: ASSIGNED → RESOLVED
Closed: 11 years ago
No longer depends on: 885926
Resolution: --- → FIXED
Target Milestone: --- → Firefox 28
You need to log in before you can comment on or make changes to this bug.