Last Comment Bug 880611 - (australis-ts) Investigate 3% regression on ts_paint on UX
(australis-ts)
: Investigate 3% regression on ts_paint on UX
Status: RESOLVED FIXED
: meta, perf
Product: Firefox
Classification: Client Software
Component: Theme (show other bugs)
: Trunk
: All All
: -- normal (vote)
: Firefox 28
Assigned To: Nobody; OK to take it and work on it
:
:
Mentors:
Depends on: 888571 888800 889597 889611 australis-tpaint 890105 890476 891104 892809 893682 894099 897260 901016 902097 904924 910283
Blocks: australis-tabs-perf
  Show dependency treegraph
 
Reported: 2013-06-07 00:50 PDT by Matthew N. [:MattN] (In Taipei until Sep. 23)
Modified: 2013-11-20 05:51 PST (History)
17 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
Hide the panel by default (3.06 KB, patch)
2013-07-02 14:36 PDT, :Gijs Kruitbosch
no flags Details | Diff | Splinter Review
Screenshot of profiler showing decoded images (159.28 KB, image/png)
2013-07-04 04:57 PDT, Matthew N. [:MattN] (In Taipei until Sep. 23)
no flags Details

Comment 1 Matthew N. [:MattN] (In Taipei until Sep. 23) 2013-06-19 23:43:09 PDT
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
Comment 2 Mike Conley (:mconley) - (needinfo me!) 2013-06-20 09:42:59 PDT
Bumping these to M8, since M7 finished yesterday.
Comment 3 Jared Wein [:jaws] (please needinfo? me) 2013-06-20 16:42:36 PDT
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)?
Comment 4 Matthew N. [:MattN] (In Taipei until Sep. 23) 2013-06-20 16:43:52 PDT
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.
Comment 5 Blair McBride [:Unfocused] (UNAVAILABLE) 2013-06-20 17:02:14 PDT
(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.
Comment 6 Mike Conley (:mconley) - (needinfo me!) 2013-06-20 17:37:00 PDT
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.
Comment 7 Jared Wein [:jaws] (please needinfo? me) 2013-06-20 18:23:44 PDT
(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.
Comment 8 Jared Wein [:jaws] (please needinfo? me) 2013-06-20 18:54:44 PDT
(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.
Comment 9 Matthew N. [:MattN] (In Taipei until Sep. 23) 2013-06-20 23:54:06 PDT
(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 :(
Comment 10 Mike Conley (:mconley) - (needinfo me!) 2013-06-21 08:10:33 PDT
That was unexpected. :/ Ok, let me try something else...
Comment 11 Mike Conley (:mconley) - (needinfo me!) 2013-06-21 08:16:30 PDT
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
Comment 12 Mike Conley (:mconley) - (needinfo me!) 2013-06-21 10:36:14 PDT
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.
Comment 13 Mike Conley (:mconley) - (needinfo me!) 2013-06-21 14:33:56 PDT
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
Comment 14 Mike Conley (:mconley) - (needinfo me!) 2013-06-21 16:35:16 PDT
Results on that try build are very encouraging.

I've filed bug 885926 to switch to getElementsByAttribute for palette queries.
Comment 15 Mike Conley (:mconley) - (needinfo me!) 2013-06-22 15:55:59 PDT
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...
Comment 17 :Gijs Kruitbosch 2013-06-27 17:58:56 PDT
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...
Comment 18 :Gijs Kruitbosch 2013-06-27 18:10:24 PDT
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.
Comment 19 :Gijs Kruitbosch 2013-06-27 18:25:01 PDT
Try push which I hope will scrape us at least a bit of a win: https://tbpl.mozilla.org/?tree=Try&rev=73d9d486abc5
Comment 20 :Gijs Kruitbosch 2013-06-27 21:44:51 PDT
(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. :-\
Comment 21 Mike Conley (:mconley) - (needinfo me!) 2013-06-28 11:31:37 PDT
Captured a start-up profile on my Linux machine:

http://people.mozilla.com/~bgirard/cleopatra/#report=2662b2f3d0d81795ab0c1d22e821c31105395fbe
Comment 22 Mike Conley (:mconley) - (needinfo me!) 2013-06-28 12:49:55 PDT
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
Comment 23 Matthew N. [:MattN] (In Taipei until Sep. 23) 2013-07-02 00:35:09 PDT
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
Comment 24 :Gijs Kruitbosch 2013-07-02 03:02:21 PDT
(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.
Comment 25 Matthew N. [:MattN] (In Taipei until Sep. 23) 2013-07-02 13:40:49 PDT
(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
Comment 26 Justin Dolske [:Dolske] 2013-07-02 13:47:51 PDT
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.
Comment 27 :Gijs Kruitbosch 2013-07-02 14:36:14 PDT
Created attachment 770425 [details] [diff] [review]
Hide the panel by default

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.
Comment 28 Matthew N. [:MattN] (In Taipei until Sep. 23) 2013-07-02 17:47:21 PDT
More bisection between B and D:
https://docs.google.com/spreadsheet/ccc?key=0Asj8iLTl0K0UdDcxemJEWVVXWTlKek1wR09iS2FsOXc&usp=sharing
Comment 29 :Gijs Kruitbosch 2013-07-03 07:47:09 PDT
(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.
Comment 30 :Gijs Kruitbosch 2013-07-03 16:36:19 PDT
Progress! See row 7 of the spreadsheet:

https://docs.google.com/a/mozilla.com/spreadsheet/ccc?key=0Asj8iLTl0K0UdDcxemJEWVVXWTlKek1wR09iS2FsOXc#gid=0
Comment 31 :Gijs Kruitbosch 2013-07-04 04:36:43 PDT
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
Comment 32 Matthew N. [:MattN] (In Taipei until Sep. 23) 2013-07-04 04:57:32 PDT
Created attachment 771293 [details]
Screenshot of profiler showing decoded 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.
Comment 33 Justin Dolske [:Dolske] 2013-07-11 16:06:37 PDT
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.
Comment 34 Matthew N. [:MattN] (In Taipei until Sep. 23) 2013-07-30 22:18:09 PDT
This is now down to ~3% worst case on XP PGO ts_paint, medium, & max.
Comment 35 Mike Conley (:mconley) - (needinfo me!) 2013-10-16 21:02:55 PDT
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.
Comment 36 Matthew N. [:MattN] (In Taipei until Sep. 23) 2013-11-20 02:14:50 PST
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

Note You need to log in before you can comment on or make changes to this bug.