237842 - Perf: malformed page with many <select>'s slows Gecko down terribly

Status: RESOLVED WORKSFORME

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

Description

[u81239]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.6) Gecko/20040206 Firefox/0.8
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.6) Gecko/20040206 Firefox/0.8

The attached malformed page causes Mozilla 1.7a, Firefox 0.8 and Firefox CVS to
suffer from terrible slowdowns - makes nice crash code! -_-;;

Anyways, so that you know, it is actually one of the testcases (the fourth) of
bug 237775.


~Grauw

Reproducible: Always
Steps to Reproduce:
1. Go to testcase
2. Try to do stuff, and wait...

Actual Results:  
100% CPU usage, everything is terribly slow.

Expected Results:  
Should render as fast as a regular page.

Comment 1

[u81239]

Cc Boris Zbarsky, add perf keyword, add to blocking list of bug 71668
performance issues tracker bug.

Don't know exactly what category to put this in, so I choose Browser-General.
Let anyone who knows better relocate it as appropriate :).

Hope I did everything right.


~Grauw

Comment 2

[Boris Zbarsky [:bzbarsky]]

What attached page?  ;)

Comment 3

[u81239]

Attachment: Test case

oops ^_^;;

Comment 4

[Boris Zbarsky [:bzbarsky]]

OK, so there seem to be several issues here:

1) The testcase is 230KB.

2) <tr> is a monolithic container in the content sink.  So we'll never notify
   while inside a <tr>.  It looks like that was added for bug 27056.
   Unfortunately, the entire page is inside a single <tr>.  So we do no
   incremental rendering on this page at all.  Now we're loading a huge page,
   and we'll show it when we're all done.  This is the primary problem reporter
   is seeing.  Could we maybe change from treating <tr> as monolithic to just
   notifying more rarely or something?  But see below.

3) If I change <tr> and <select> to not be monolithic (so that the page should
   render incrementally), I still don't really see that happening!  I see the
   sink notifying 679 times during page load, and I see us interrupting the
   parser 41 times (I wasn't moving the mouse, so it was in slow mode), but I
   still don't see any incremental layout.  I'm not sure why.  We should figure
   it out....

4) If I move the mouse (so we use the shorter interrupt interval, I get 3 or 4
   incremental reflows).

5) General performance on the testcase:

Of 526520 total profiler hits, 177491 are under
nsContainerFrame::PositionChildViews.  Lots of moving of views, their
corresponding widgets, gdk windows, etc, etc.

167670 hits are under nsBlockFrame::ReflowLine.  That includes reflow of all
sorts of stuff, really....  In any case, 47412 of those hits end up under
nsComboboxControlFrame::Reflow (less than 10% of the total hits).

It looks like all that mouse moving, while allowing the sink to interrupt, also
triggered a lot of incremental reflows (via the draggesture stuff in the ESM --
nsEventStateManager::GenerateDragGesture flushes pending reflows; not sure why
it's being called here, though, since I didn't have the mouse button down).

It also looks like we spend a bunch of time calling SetCursor() on windows,
which ends up calling XFlush() (ewwww).  I guess that's for all those widgets we
have to create for the selects....

74897 of the hits are under nsCSSFrameConstructor::InitializeSelectFrame
(creating widgets, scrollframes, etc.  44451 hits are under
nsCSSFrameConstructor::CreateAnonymousFrames (the stuff inside the select).

If I replace "select" by "sele" throughout the file, it renders _very_ quickly.
 So this is definitely related to the <select> business.  Even if I give opacity
to all the <sele> elements it's pretty quick

My diagnosis is that lots of widgets are slow when using the gtk1 toolkit (dunno
about the others).  :(

Comment 5

[Jens-Uwe]

i think Boris comment #4 confirmed this...

Comment 6

[Boris Zbarsky [:bzbarsky]]

I think that if I meant to confirm it, I'd have done so....

I also think that confirming a bug in browser-general is a good way to kill it
forever.

Over to DOM for the content sink issue, I guess.

Comment 7

[u81239]

Related to / dupe of bug 236703 ?

At least the sample page loading behaviour is also slow :).


~Grauw

Comment 8

[Boris Zbarsky [:bzbarsky]]

Laurens, note the profile data I posted in this bug.  How would it possibly be
related to bug 236703, eh?  Please do read bugs before commenting on them....

Comment 9

[David Harper]

Not sure if this is totally related to this bug, but I have 11 Select Boxes,
that get filled from a database on a page. Each box has at least 50 values in it. 

Internet Explorer manages to render the page in 6 seconds, whereas Firefox takes
12. I could really do with things being speeded up :)

Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.7.2) Gecko/20040810
Firefox/0.9.1+

Comment 10

[Boris Zbarsky [:bzbarsky]]

(In reply to comment #9)
> Not sure if this is totally related to this bug

Chances are, it's not.

> I could really do with things being speeded up :)

File a bug, cc me, and point to the page.  As it is, we need to guess what your
file looks like... not conducive to speeding anything up.

Comment 11

[Wayne Mery (:wsmwk)]

would bug 335984 help?

loads in 12 seconds current trunk, <2sec IE8  (desktop vista)

Comment 12

[Boris Zbarsky [:bzbarsky]]

> would bug 335984 help?

Not really, no.  A profile would.

Comment 13

[Boris Zbarsky [:bzbarsky]]

OK, so the load looks like this (unload sucks too, but let's not worry about that for now):

~50% under nsIView::CreateWidget in cocoa widgetry stuff (on Mac, obviously).
12% or so under reflow.
17% frame construction and style resolution plus xbl stuff
5% setting attrs on the scrollbars after reflow

And various minor stuff (the parser creating nodes, gc, etc).

I wonder whether we could somehow avoid creating all those widgets eagerly...

Comment 14

[Robert O'Callahan (:roc) (email my personal email if necessary)]

We're constructing the dropdown widgets for the selects? Yeah, we should do that lazily. In fact, we should just construct the dropdown widget when we need to show the dropdown, and destroy it when we hide the dropdown. Probably a small but significant pageload win. Sounds like something Ehsan might be interested in.

Comment 15

[Boris Zbarsky [:bzbarsky]]

> We're constructing the dropdown widgets for the selects? 

Yes.  And then making sure to hide them, etc, etc.

Comment 16

[Daniel C]

Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.3a5pre) Gecko/20100421 Minefield/3.7a5pre

I still see this, and came across this bug after commenting in bug 115388. The URL in that bug (http://greymagic.com/dagon/ff.html) has an option for which form element to render. Choosing 15000 select elements causes the browser (and X) to freeze and max-out the CPU for a long time before finally displaying the alert and the page. This is on an old P4 2.8 GHz.

"we should just construct the dropdown widget when we need
to show the dropdown" This sounds promising.

If there's anything I can do to help diagnose or test this please let me know.

Comment 17

[Boris Zbarsky [:bzbarsky]]

Taking this so I don't lose track of it, but Ehsan, feel free to steal it if you want!  I'm not planning to work on this before 2.0 at the moment.

Comment 18

[Boris Zbarsky [:bzbarsky]]

Actually, better to just file a targeted bug on the widget issue.

Comment 19

[(no longer active)]

Attachment: Test case

I was experimenting with my patch in bug 610391, so I modified the test case here slightly.  I'm attaching the modified test case here.  Here are the numbers before and after the patch.

Before:
Construction: 4699ms
Destruction: 8948ms

After:
Construction: 797ms
Destruction: 1909ms

Comment 20

[Boris Zbarsky [:bzbarsky]]

Sounds good.  ;)  We can reprofile here once that lands.

Comment 21

[Boris Zbarsky [:bzbarsky]]

That last testcase should be subtracting start.getTime() for the destruction test, not begin.getTime().

I did some profiles; analysis tonight.

Comment 22

[(no longer active)]

(In reply to comment #21)
> That last testcase should be subtracting start.getTime() for the destruction
> test, not begin.getTime().

Oh, embarrassing.  This explains the huge tear-down times.  ;-)

> I did some profiles; analysis tonight.

Eager to see them.

Comment 23

[Boris Zbarsky [:bzbarsky]]

OK, so the "construction" profile:

65% is reflow, breaking down as:
  23% the combination of all the attr-setting scrollframe does after reflow and
      the reflow flush it triggers afterward.  We really need a better setup
      for this.
   8% nsBlockFrame::ClearFloats getting intrinsic min widths for a bunch of
      nested tables.  About 3/4 of this is the min intrinsic width computation
      for the comboboxes, and about half of this is GetDesiredScrollbarSizes,
      which ends up in the sprocket layout pref size mess on the scrollbars. 
      See "better setup" above!
  18% Reflowing combobox dropdowns.
   8% Reflowing combobox display areas and dropmarkers
   plus some minor stuff.

34% is frame construction, breaking down as:
  28% under ConstructSelectFrame (6% the CreateAnonymousFrames for the select!,
      17% in scrollbar frame construction, the rest is real work).   Hey, we
      need a better scrollframe setup!
   6% the various table bits involved (style resolution and frame construction
      for them).

Comment 24

[Boris Zbarsky [:bzbarsky]]

"destruction" profile:

 8% releasing and destroying all the AnonymousContentDestroyer runnables (which
    releases and destroys the DOM nodes, etc).
19% calling AnonymousContentDestroyer::Run (half XBL crud, and half
    releasing+destroying the content nodes involved).
 7% memcpy removing elements from sBlockedScriptRunners in
    nsContentUtils::RemoveScriptBlocker.
16% nsFrameManager::CaptureFrameState under RecreateFramesFor.
50% under frame destruction; notable here is 13% in (not under)
    nsView::RemoveChild called by ~nsView, 5% hashtable ops (half removing stuff
    from the frame property table, plus some nsPresArena stuff), a few percent
    under nsSVGEffects::InvalidateDirectRenderingObservers, a few percent after
    free(), a few percent in (not under) nsLineBox::DeleteLineList, etc, etc).

Comment 25

[(no longer active)]

(In reply to comment #23)
> OK, so the "construction" profile:
> 
> 65% is reflow, breaking down as:
>   23% the combination of all the attr-setting scrollframe does after reflow and
>       the reflow flush it triggers afterward.  We really need a better setup
>       for this.

I've seen this in *so many* profiles, FWIW.

>   18% Reflowing combobox dropdowns.

Do we need to do that before we are going to display the drop-down?

> 34% is frame construction, breaking down as:
>   28% under ConstructSelectFrame (6% the CreateAnonymousFrames for the select!,

Hmm, that 6% looks a lot to me.  What are we doing in CreateAnonymousContent which is taking so long?

Comment 26

[(no longer active)]

(In reply to comment #24)
> "destruction" profile:
> 
>  8% releasing and destroying all the AnonymousContentDestroyer runnables (which
>     releases and destroys the DOM nodes, etc).
> 19% calling AnonymousContentDestroyer::Run (half XBL crud, and half
>     releasing+destroying the content nodes involved).

Do you remember what's the expensive part there?

>  7% memcpy removing elements from sBlockedScriptRunners in
>     nsContentUtils::RemoveScriptBlocker.

That seems very wasteful.  Can't we be smarter there, by like not removing the script blockers until we run them all, and then just remove them in a single operation?

> 16% nsFrameManager::CaptureFrameState under RecreateFramesFor.
> 50% under frame destruction; notable here is 13% in (not under)
>     nsView::RemoveChild called by ~nsView, 5% hashtable ops (half removing
> stuff

So, I don't really know a lot about our view system, and why it's necessary, but is there any way for us to avoid creating a million views here?

>     from the frame property table, plus some nsPresArena stuff), a few percent
>     under nsSVGEffects::InvalidateDirectRenderingObservers, a few percent after

Do we have any SVG effects applied here?

>     free(), a few percent in (not under) nsLineBox::DeleteLineList, etc, etc).

Comment 27

[Boris Zbarsky [:bzbarsky]]

> Do we need to do that before we are going to display the drop-down?

For this testcase, more or less yes.  The auto width of a combobox depends on the widths of all the options, which is exactly the work needed to reflow the dropdown... so we just do that.

> Hmm, that 6% looks a lot to me.  What are we doing in CreateAnonymousContent
> which is taking so long?

CreateAnonymousFrames, not CreateAnonymousContent.  That 6% breaks down like this:

 1.9% CreateAnonymousContent, breaking down as:
   1.2% SetAttr called from nsComboboxControlFrame::CreateAnonymousContent
   0.3% NS_NewHTMLElement
   0.1% nsListControlFrame::GetSelectedIndex
   0.1% nsListControlFrame::GetOptionText
   0.1% nsGenericElement::AddEventListenerByIID
   0.1% nsAString::SetLength
 0.5% nsHTMLInputElement::BindToTree
 0.2% under nsComboboxControlFrame::CreateFrameFor
 3.2% under ConstructFrame breaking down as:
   0.5% nsButtonFrameRenderer::Init (mostly probing the pseudo style)
   0.3% CreateAnonymousFrames for that button
   0.3% nsBlockFrame::AppendFrames for the kids of the button (?)
   0.3% style resolution, calls into the counter manager, etc under
        ConstructButtonFrame.
   1.6% resolving the style for the button

In particular, since the dropmarker is an <input type="button"> it ends up having to check the type attribute selectors in forms.css; just doing that is a third of the style-resolution time there (0.5% of total).

So the short story on the 6% is that a combobox has a bunch of structure inside it... :(

> Do you remember what's the expensive part there?

Um... regenerating the profile takes about 30 seconds, so "remember" is not an issue.  ;)

I'm seeing things like this:

 3.5% under ~nsXBLBinding, 0.9% is free() and the rest is
      UninstallAnonymousContent().  This latter does nsGenericElement:AddRef,
      UnbindFromTree, GetSafeChildAt, each at about 0.9%.
 2.7% UninstallAnonymousContent called from nsXBLBinding::ChangeDocument.  All
      of this is under UnbindFromTree calling free() and more
      nsXBLBinding::ChangeDocument, which gets child counts.
 2.7% under nsXBLBinding::UnhookEventHandlers
   2% under ~nsGenericElement, mostly clearing the child array which destroys
      the kids, etc; the time is mostly under free().
   2% nsHTMLInputElement::UnbindFromTree recomputing validity state and calling
      IsValueMissing and such, and calling UnbindFromTree on some XUL element.
   
That's mostly the breakdown (this time Run was about 16% of total time).

> That seems very wasteful.

Yeah.  We should file a bug on this....

> but is there any way for us to avoid creating a million views here?

That's a question for roc.

> Do we have any SVG effects applied here?

No, but nsFrame::DestroyFrom always calls that function.

Comment 28

[(no longer active)]

(In reply to comment #27)
> > Do we need to do that before we are going to display the drop-down?
> 
> For this testcase, more or less yes.  The auto width of a combobox depends on
> the widths of all the options, which is exactly the work needed to reflow the
> dropdown... so we just do that.

I see.  Makes sense.

> In particular, since the dropmarker is an <input type="button"> it ends up
> having to check the type attribute selectors in forms.css; just doing that is a
> third of the style-resolution time there (0.5% of total).

Hmm, is there any reason why it's not a <button>?  I was reading this code today, and it occurred to me, but I didn't know what the implications of such a change would be.

> I'm seeing things like this:
> 
>  3.5% under ~nsXBLBinding, 0.9% is free() and the rest is
>       UninstallAnonymousContent().  This latter does nsGenericElement:AddRef,
>       UnbindFromTree, GetSafeChildAt, each at about 0.9%.
>  2.7% UninstallAnonymousContent called from nsXBLBinding::ChangeDocument.  All
>       of this is under UnbindFromTree calling free() and more
>       nsXBLBinding::ChangeDocument, which gets child counts.
>  2.7% under nsXBLBinding::UnhookEventHandlers
>    2% under ~nsGenericElement, mostly clearing the child array which destroys
>       the kids, etc; the time is mostly under free().

I'm kind of noting that free is turning up a lot in these profiles...

>    2% nsHTMLInputElement::UnbindFromTree recomputing validity state and calling
>       IsValueMissing and such, and calling UnbindFromTree on some XUL element.

Another reason why using <button> might be better...

> > That seems very wasteful.
> 
> Yeah.  We should file a bug on this....

Filed bug 643885.

> > Do we have any SVG effects applied here?
> 
> No, but nsFrame::DestroyFrom always calls that function.

Which part of it is getting most of the heat?  This seems very wasteful, so I'm wondering if we should look into optimizing it.

Comment 29

[Boris Zbarsky [:bzbarsky]]

> Hmm, is there any reason why it's not a <button>?

Nothing obvious.  We should consider trying it that.

> I'm kind of noting that free is turning up a lot in these profiles...

Note that I'm on mac.  The built-in allocator's free() here is dog-slow, and we're not using jemalloc on Mac yet.  With jemalloc, this cost might disappear.

> Which part of it is getting most of the heat? 

If shark is not lying to me, the IsElement() check (and in particlar, L2 cache misses on the flags word).

Comment 30

[(no longer active)]

(In reply to comment #29)
> > Hmm, is there any reason why it's not a <button>?
> 
> Nothing obvious.  We should consider trying it that.

Filed bug 643945.

> > I'm kind of noting that free is turning up a lot in these profiles...
> 
> Note that I'm on mac.  The built-in allocator's free() here is dog-slow, and
> we're not using jemalloc on Mac yet.  With jemalloc, this cost might disappear.

Good point.

> > Which part of it is getting most of the heat? 
> 
> If shark is not lying to me, the IsElement() check (and in particlar, L2 cache
> misses on the flags word).

Hmm.  Can't we add a flag to the frame indicating that it (or one of its parent) has an SVG effect applied, in order to avoid doing this work if that flag is not set?

Comment 31

[Robert O'Callahan (:roc) (email my personal email if necessary)]

(In reply to comment #25)
> (In reply to comment #23)
> > OK, so the "construction" profile:
> > 
> > 65% is reflow, breaking down as:
> >   23% the combination of all the attr-setting scrollframe does after reflow and
> >       the reflow flush it triggers afterward.  We really need a better setup
> >       for this.
> 
> I've seen this in *so many* profiles, FWIW.

We could probably win quite a lot of performance for all kinds of things by creating a single anonymous element that implements a complete scrollbar (instead of the complex XBL binding we currently use), and simplify a lot of stuff too. We could give that element a proper non-element-based API and move the thumb without having to do reflow. I thought there was a bug for this but I can't find it.

Comment 32

[Robert O'Callahan (:roc) (email my personal email if necessary)]

(FWIW I think that bug is definitely worth having someone work on in the short-medium term.)

Comment 33

[(no longer active)]

(In reply to comment #32)
> (FWIW I think that bug is definitely worth having someone work on in the
> short-medium term.)

Do you have anybody in particular in mind?

Comment 34

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Not really.

Comment 35

[(no longer active)]

(In reply to comment #31)
> We could probably win quite a lot of performance for all kinds of things by
> creating a single anonymous element that implements a complete scrollbar
> (instead of the complex XBL binding we currently use), and simplify a lot of
> stuff too. We could give that element a proper non-element-based API and move
> the thumb without having to do reflow. I thought there was a bug for this but I
> can't find it.

I went ahead and filed bug 645563.

Comment 36

[Firefox Bug Husbandry Bot]

https://bugzilla.mozilla.org/show_bug.cgi?id=1472046

Move all DOM bugs that haven’t been updated in more than 3 years and has no one currently assigned to P5.

If you have questions, please contact :mdaly.

Comment 37

[Mayank Bansal]

Nightly: construction 55ms, destruction 1055ms
Chrome: similar timings.

If I remove the timeout : construction 55ms, destruction 80ms (https://share.firefox.dev/3AHU3CK)
Chrome: similar.

Closing as Worksforme.