439371 - ~2500 positioned DIVs testcase is slower in Firefox than Chromium

Status: RESOLVED WORKSFORME

(Core :: Layout, defect)

Description

[Mike Schroepfer]

Recently cited in lifehacker performance comparison of browsers.  We are significantly slower than Safari 3.1.1 on my MacOS machine (on the order of 10x) - although I'm not sure if that is accounted for as a result of the different onload handling.

Either way would be worth profiling to see where the time is going.

Comment 1

[Boris Zbarsky [:bzbarsky]]

10x slower on which?  The pageload?  Or the "Get All DIV's" button press?  The former could certainly be affected by onload wackiness, since it runs onload.

Also, are we just measuring the time, or are we also interested in responsiveness (for the pageload)?

In any case, I guess I'll profile both and see how it goes.

Comment 2

[Boris Zbarsky [:bzbarsky]]

Attachment: The testcase

Comment 3

[Boris Zbarsky [:bzbarsky]]

OK, the 10x is certainly the load time.  The "get all divs" time we're slower by 1x-3x, depending.

Comment 4

[Boris Zbarsky [:bzbarsky]]

OK, adding 

  document.body.offsetWidth;

before the final time check doesn't change our time, but increases Safari's by a factor of 3.  So they're certainly firing onload before doing final page layout.

That still leaves a 3x difference on the pageload, of course.

Comment 5

[Boris Zbarsky [:bzbarsky]]

I should also note that at least in Gecko the "get all divs" time doesn't include _any_ of the time needed for recomputing the style data or repainting, as the testcase is written.  It's a pure DOM access and CSS parser and "front end" data structures performance test.

Comment 6

[Boris Zbarsky [:bzbarsky]]

OK.  Profiling pageload.

First, the bottom-up profile:

4.2%	CoreGraphics	argb32_mark_constantmask	
3.3%	CoreGraphics	aa_render	
2.7%	CoreGraphics	aa_render_shape	
2.6%	libSystem.B.dylib	szone_malloc	
1.8%	libSystem.B.dylib	szone_free	
1.8%	libxpcom_core.dylib	SearchTable	
1.7%	CoreGraphics	sseCGSFill8by1	
1.7%	libgklayout.dylib	SelectorMatches(RuleProcessorData&, nsCSSSelector*, int, nsIAtom*, int, int*)	
1.6%	libhtmlpars.dylib	__i686.get_pc_thunk.bx	
1.2%	libi18n.dylib	nsCaseConversionImp2::CaseInsensitiveCompare(unsigned short const*, unsigned short const*, unsigned, int*)	
1.2%	CoreGraphics	sseCGSBlackDeepMaskCopyARGB8888	
0.9%	libgklayout.dylib	nsTextFrame::Reflow(nsPresContext*, nsHTMLReflowMetrics&, nsHTMLReflowState const&, unsigned&)	

So CoreGraphics is at least 15% of the total time right there.  If I charge the CoreGraphics library to callers, and the same with libRIP, then of course the time is under cairo.  If I charge libthebes and libgfxthebes to callers too, to see what layout is doing here, the bottom-up profile looks like:

12.2%	libgklayout.dylib	FillFastBorderPath(gfxContext*, gfxRect const&, gfxRect const&, double const*, double const*, int, gfxRGBA const&)	
4.6%	libgklayout.dylib	nsTextFrame::PaintText(nsIRenderingContext*, nsPoint, nsRect const&)	
3.2%	libgklayout.dylib	nsCSSRendering::PaintBackgroundColor(nsPresContext*, nsIRenderingContext&, nsIFrame*, nsRect const&, nsStyleBackground const&, nsStyleBorder const&, nsStylePadding const&, int)	
2.6%	libSystem.B.dylib	szone_malloc	
2.3%	libgklayout.dylib	nsTextFrame::Reflow(nsPresContext*, nsHTMLReflowMetrics&, nsHTMLReflowState const&, unsigned&)	
1.9%	libxpcom_core.dylib	SearchTable	
1.8%	libSystem.B.dylib	szone_free	
1.7%	libgklayout.dylib	BuildTextRunsScanner::BuildTextRunForFrames(void*)	
1.7%	libgklayout.dylib	SelectorMatches(RuleProcessorData&, nsCSSSelector*, int, nsIAtom*, int, int*)	

So a lot of time painting borders (I think vlad had some thoughts on doing this better anyway), but more importantly a lot of painting in general.  Might be interesting to see how many times we paint here during the pageload; compositor might help with that.  In any case, painting is looking like 20% of total time here, basically.

Most of the calls to malloc are text fragment construction, child array allocation, textrun allocation, text node allocation, view creation, space manager data structures.

Looking top-down:

  * About 7% reflowing when about to paint
  * About 28% actually painting
  * About 31% running reflow events
  * About 22% in parser, DOM construction as far as I can tell
  * About 8% in sink notifications (frame construction)

Nothing obvious jumps out at me here, to be honest.  That is, no clear hotspots other than the border painting.  The usual time frittered away all over the place in the parser in little bits, none of them more than fractions of a percent.  Under reflow, the closest thing to hotspots are textframe reflow (7% of reflow), ensuring textruns (20%), case-insensitive string comparisons (in nsFont::BaseEquals, when doing nsFontCache::GetMetricsFor).

But there's also plenty of stuff like positioning views (due to the rel pos frames), etc.

I sort of wonder how this would all perform with compositor, to be honest.  In any case, it looks like a pretty "typical" pageload, no surprises.

Comment 7

[Boris Zbarsky [:bzbarsky]]

Profiling the "get all divs" thing.

The time spent under SetBackgroundColor is 30% of total.  It breaks down as 1/4 CSS parsing, 1/6 creating all those new inline style rule objects and setting them in the attr array (a lot of this is growing the attr array), about 1/20 in refcounting and such, and and about 1/2 handling the new style rule: setting it in the attr, checking for mutation listeners, more refcounting, notifying the presshell, etc.  Only about a third of this 1/2 gets to the frame constructor, and most of that is checking for attribute-dependent style, posting restyle events, getting primary frames, calling AttributeChanged on the frame.

10% of the time is the JS/xpconnect overhead involved in calling SetBackgroundColor.

25% seems to be getting all those style declaration objects.  At least 3/4 of this is xpconnect JS-wrapping the C++ object; some of the remaining 1/4 is also xpconnect overhead.

25% is getting all those nodes by index.  1/15 of this or so is the actual getting part in C++; the rest is JS and XPConnect overhead of various sorts (property lookup, JS-wrapping the node, etc).

Comment 8

[Mike Schroepfer]

(In reply to comment #1)
> 10x slower on which?  The pageload?  Or the "Get All DIV's" button press?  The
> former could certainly be affected by onload wackiness, since it runs onload.
> 

Yep pageload - which is why I mentioned the onload craziness. 

Comment 9

[Mike Schroepfer]

Are there other ways beside compositor to basically avoid a bunch of the work - e.g. at a 250ms total render time (what it is on my machine) shouldn't we be doing 0-1 reflows?

Comment 10

[Boris Zbarsky [:bzbarsky]]

The 250ms should only affect painting, not reflow, if you're talking about paint suppression.  It doesn't suppress reflow.  So we'll reflow basically every time the parser backs off to the event loop.

I wouldn't be at all surprised if we back off a good bit here.  I think we do that every 3ms at the most if the user has moved the mouse or used the keyboard "recently" (in the last 0.75 seconds by default).

Of course once we've been loading for more than 0.75 seconds we go into our "long page, be faster and less responsive" mode, where we only back off once every 360ms or so.  But this testcase is too small to hit that.

So other than compositor, there is retuning (or changing!) all that logic in the sink, esp. since the times it uses are based on tests with 1999-era hardware.

Comment 11

[Mike Schroepfer]

Do you have any pointers to the knobs in question?  I'd be curious if we took a more aggressive "don't interrupt for 100-200ms" what the tradeoff between time to complete and responsiveness is.

Comment 12

[Boris Zbarsky [:bzbarsky]]

There are a whole bunch of preference gets in nsContentSink::Init:

"content.notify.ontimer": whether to notify (triggering frame construction) once enough time has passed (or just at end of parse)

"content.notify.backoffcount": number of times to notify off a timer before switching to waiting to end of parse 

"content.notify.interval": interval between timed notifications in "idle" mode, in microseconds.  In non-idle mode, this is always 1ms.

"content.max.tokenizing.time": time after which we should suspend the parser and return to the main event loop, in "idle" mode.  In non-idle mode, this is always 3ms.

"content.switch.threshold": period with which we should test whether we're in idle mode.

There are some comments in this method about what the frobs do and why they're currently set the way they are.

Note that the "don't notify ever" thing doesn't work that well: we have to notify if we're adding kids to a parent we already notified on, and reflow flushes out all notifications.  So we do a reflow, end up with some parents (e.g. <body>) that are notified on, then any time a kid is added to them we have to notify and post a reflow event, so if we then get back to the main event loop we'll flush notifications when that event fires.

This is one of the interactions that compositor could seriously improve.

Comment 13

[Ryan VanderMeulen [:RyanVM]]

For the pageload, we're still about 50% slower than Chrome on my system (~80ms vs ~120ms). For "Get All DIVs", Firefox is about 3-5x slower than Chrome (though Firefox' number bounces around a lot).

Comment 14

[Boris Zbarsky [:bzbarsky]]

It's probably worth filing separate bugs on the pageload and the Get All Divs bit, and track them here...

For what it's worth, the background-color setting is now closer to 60% of total, not 30% (because the other stuff got faster).

Comment 15

[Gregory Pappas [:gregp]]

The "Get all DIV's" part of this test performs exactly the same in Nightly and Chromium on my machine, 1ms in both.

This test isn't particularly stable but regarding pageload, I'm seeing about 30ms in Firefox and 16ms in Chromium.

https://share.firefox.dev/3nQSdcV

Comment 16

[Daniel Holbert [:dholbert]]

(In reply to Gregory Pappas [:gregp] from comment #15)

The "Get all DIV's" part of this test performs exactly the same in Nightly and Chromium on my machine, 1ms in both.

This test isn't particularly stable but regarding pageload, I'm seeing about 30ms in Firefox and 16ms in Chromium.

On my Ubuntu 22.04 system, I'm seeing values that are a bit higher, but still consistent between Firefox and Chrome -- both are in the range of 45-60ms.

Also, if I scale up the number of divs (e.g. copypasting the whole pile-o'-divs 5x) to ~12481, I get larger values, but Firefox and Chrome are still on-par -- if anything, Firefox is a little bit faster (Firefox Nightly: 149ms-163ms, vs. Chrome dev: 182-195ms)

Also, the performance difference from comment 15 (30ms vs. 16ms) is a small enough delta (and also only < 2x as compared to 10x in the original report) that I'm not especially worried, unless it were extremely reliable and representative of some real-world workload.

Given all the above, I think we can consider the original issue here to have been fixed, basically. (There's a chance there's a remaining small discrepancy per comment 15, but it's small & potentially hardware-specific, and not obviously worth tracking or worrying about.)

Comment 17

[Daniel Holbert [:dholbert]]

Attachment: testcase 2 with 5x as many divs (12481)

(In reply to Daniel Holbert [:dholbert] from comment #16)

Also, if I scale up the number of divs (e.g. copypasting the whole pile-o'-divs 5x) to ~12481, I get larger values, but Firefox and Chrome are still on-par -- if anything, Firefox is a little bit faster (Firefox Nightly: 149ms-163ms, vs. Chrome dev: 182-195ms)

Here's that testcase, for what it's worth.

gregp, I'm mildly curious if you're still seeing Chrome faster than Firefox on this version (and if it's a substantial difference). If so, that might be something I want to dig into (as follow from your observation in comment 15).

Comment 18

[Gregory Pappas [:gregp]]

Hi Daniel! Thanks for the enhanced test case.

Interestingly, in the 5x-as-many-divs version, Firefox is consistently faster on my machine.

Nightly: 289ms
Chrome: 415ms

Seeing this consistently across runs, very fun!

Comment 19

[Daniel Holbert [:dholbert]]

Thanks! That makes me more comfortable about closing this out.