514275 - XUL stuff reflows too often on startup

Status: NEW

(Core :: XUL, defect, P3)

Description

[(dormant account)]

We should try to debug and reduce the number of reflows on startup. This is taking a few seconds of startup on N810 and it doesn't help on the desktop.

bz suggested to look at backtrace to see who calls nsNeedsReflow(). Apparently sticking in an ns_error() call and XPCOM_DEBUG_BREAK=stack is a cross-platform way of getting backtraces.

Comment 1

[(dormant account)]

Forgot to mention, looking at callers of ProcessReflowCallbacks() is also important... It processes things that are unsafe during reflow and possibly causes bonus reflows

Comment 2

[Joel Reymont (:joelr)]

I have 68 calls to nsFrame::BoxReflow until BrowserStartup (JS) returns. These 2 stack traces seem to repeat themselves:

              XUL`nsFrame::BoxReflow(nsBoxLayoutState&, nsPresContext*, nsHTMLReflowMetrics&, nsIRenderingContext*, int, int, int, int, int)+0x3d5
              XUL`nsFrame::DoLayout(nsBoxLayoutState&)+0xf8
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsSprocketLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0xbed
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsStackLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0x2a9
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsBoxFrame::Reflow(nsPresContext*, nsHTMLReflowMetrics&, nsHTMLReflowState const&, unsigned int&)+0xff
              XUL`nsContainerFrame::ReflowChild(nsIFrame*, nsPresContext*, nsHTMLReflowMetrics&, nsHTMLReflowState const&, int, int, unsigned int, unsigned int&, nsOverflowContinuationTracker*)+0x77
              XUL`ViewportFrame::Reflow(nsPresContext*, nsHTMLReflowMetrics&, nsHTMLReflowState const&, unsigned int&)+0x184
              XUL`PresShell::DoReflow(nsIFrame*, int)+0x1a8
              XUL`PresShell::ProcessReflowCommands(int)+0x173
              XUL`PresShell::FlushPendingNotifications(mozFlushType)+0x19e
              XUL`nsGfxScrollFrameInner::AsyncScrollPortEvent::Run()+0x2f
              XUL`nsThread::ProcessNextEvent(int, int*)+0xfc
              XUL`NS_ProcessNextEvent_P(nsIThread*, int)+0x2a
              XUL`nsThread::Shutdown()+0x103
              XUL`NS_InvokeByIndex_P+0x58

              XUL`nsFrame::BoxReflow(nsBoxLayoutState&, nsPresContext*, nsHTMLReflowMetrics&, nsIRenderingContext*, int, int, int, int, int)+0x3d5
              XUL`nsFrame::DoLayout(nsBoxLayoutState&)+0xf8
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsStackLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0x2a9
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsSprocketLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0xbed
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsSprocketLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0xbed
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsSprocketLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0xbed
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsSprocketLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0xbed
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsSprocketLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0xbed
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35

Comment 3

[Joel Reymont (:joelr)]

bz:so there are a few things we could talk about:
bz:1) make any given reflow pass faster (this is hard)
bz:2) reduce number of reflow passes
bz:s/this is hard/this may be hard/
bz:So one place to start would be seeing why we're doing reflow at all
bz:that is, what things cause posting of reflow events and what things trigger reflow in their post-reflow callbacks
bz:and seeing whether we can reduce or eliminate them.
joelr:post-reflow callbacks?
bz:see comment 1 in the bug
bz:firefox has about 4000 elements in its ui
bz:which means about 4000 boxes to reflow
bz:modulo optimizations, etc
bz:BoxReflow is the reflow of a single box
bz:those are the two things to look into
bz:reducing number of reflow passes
bz:and speeding up individual passes
bz:if you have info on what parts actually take up time during reflow, we should look into that
bz:I would also be interested in the number of nsIFrame::Layout calls you see during startup
bz:that's a more interesting metric to me
bz:esp. if we can chunk it up per reflow pass

Comment 4

[Joel Reymont (:joelr)]

What is a reflow pass? Where does it start and end?

Comment 5

[Joel Reymont (:joelr)]

On nsIFrame::Layout(nsBoxLayoutState&)...

elapsed: 22.8620403ms
cpu    : 9.6973901ms
count  : 534 times

This is during the first 20s of Firefox startup. 

The stack trace typically looks like this:

              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x44
              XUL`nsSprocketLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0xbed
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsSprocketLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0xbed
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsSprocketLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0xbed
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsSprocketLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0xbed
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsSprocketLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0xbed
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsStackLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0x2a9
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsBoxFrame::Reflow(nsPresContext*, nsHTMLReflowMetrics&, nsHTMLReflowState const&, unsigned int&)+0xff

or this:

              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x44
              XUL`nsStackLayout::Layout(nsIFrame*, nsBoxLayoutState&)+0x2a9
              XUL`nsBoxFrame::DoLayout(nsBoxLayoutState&)+0x35
              XUL`nsIFrame::Layout(nsBoxLayoutState&)+0x2f
              XUL`nsBoxFrame::Reflow(nsPresContext*, nsHTMLReflowMetrics&, nsHTMLReflowState const&, unsigned int&)+0xff
              XUL`nsLineLayout::ReflowFrame(nsIFrame*, unsigned int&, nsHTMLReflowMetrics*, int&)+0x36f
              XUL`nsBlockFrame::ReflowInlineFrame(nsBlockReflowState&, nsLineLayout&, nsLineList_iterator, nsIFrame*, LineReflowStatus*)+0x53
              XUL`nsBlockFrame::DoReflowInlineFrames(nsBlockReflowState&, nsLineLayout&, nsLineList_iterator, nsFlowAreaRect&, int&, nsFloatManager::SavedState*, int*, LineReflowStatus*, int)+0x188
              XUL`nsBlockFrame::ReflowInlineFrames(nsBlockReflowState&, nsLineList_iterator, int*)+0x1d2
              XUL`nsBlockFrame::ReflowLine(nsBlockReflowState&, nsLineList_iterator, int*)+0x143
              XUL`nsBlockFrame::ReflowDirtyLines(nsBlockReflowState&)+0x602
              XUL`nsBlockFrame::Reflow(nsPresContext*, nsHTMLReflowMetrics&, nsHTMLReflowState const&, unsigned int&)+0x2b9
              XUL`nsBlockReflowContext::ReflowBlock(nsRect const&, int, nsCollapsingMargin&, int, int, nsLineBox*, nsHTMLReflowState&, unsigned int&, nsBlockReflowState&)+0x102
              XUL`nsBlockFrame::ReflowBlockFrame(nsBlockReflowState&, nsLineList_iterator, int*)+0x3d8
              XUL`nsBlockFrame::ReflowLine(nsBlockReflowState&, nsLineList_iterator, int*)+0x7f
              XUL`nsBlockFrame::ReflowDirtyLines(nsBlockReflowState&)+0x602
              XUL`nsBlockFrame::Reflow(nsPresContext*, nsHTMLReflowMetrics&, nsHTMLReflowState const&, unsigned int&)+0x2b9
              XUL`nsAbsoluteContainingBlock::ReflowAbsoluteFrame(nsIFrame*, nsPresContext*, nsHTMLReflowState const&, int, int, int, nsIFrame*, unsigned int&, nsRect*)+0x1db
              XUL`nsAbsoluteContainingBlock::Reflow(nsContainerFrame*, nsPresContext*, nsHTMLReflowState const&, unsigned int&, int, int, int, int, int, nsRect*)+0x1d0
              XUL`nsBlockFrame::Reflow(nsPresContext*, nsHTMLReflowMetrics&, nsHTMLReflowState const&, unsigned int&)+0x909

The full list is here: http://gist.github.com/180554

Comment 6

[Dietrich Ayala (:dietrich)]

are there ways of constructing boxes of boxes that trigger fewer reflows? eg: should we build up complex dom structures before or after appending to a particular spot in a document? should we be using some xul elements over others?

Comment 7

[Boris Zbarsky [:bzbarsky]]

> eg: should we build up complex dom structures before or after appending to a
> particular spot in a document?

Doesn't matter for reflow.

What I'd like to know here is:

1)  How many calls to PresShell::ProcessReflowCommands are there?
2)  What are the callsites/callstacks?  Specifically, how many are off
    post-reflow callbacks, how many off of reflow events, how many off of
    explicit flushes due to someone asking for layout information?
3)  Are there cases when the loop in nsSprocketLayout::Layout ends up doing
    more than one pass?  If so, how many and how many passes?  Can we figure
    out which particular parts of the UI trigger multiple passes and why?

At least for a start.

Comment 8

[Joel Reymont (:joelr)]

Attachment: Count of PresShell::ProcessReflowCommands invocations + call sites

Comment 9

[Joel Reymont (:joelr)]

Attachment: DTrace script to count the # of invocation of ProcessReflowCommands and trigger callbacks

Comment 10

[Joel Reymont (:joelr)]

Comment on attachment 399191 [details]
Count of PresShell::ProcessReflowCommands invocations + call sites

I had 2-3 pages open and Minefield added the "Get involved" one. Will post another log, this time with a blank page.

Comment 11

[Joel Reymont (:joelr)]

Attachment: PresShell::ProcessReflowCommands during the first 20s of startup, using a blank page

I need to put in a custom probe to only count passes that do actual work. This is http://mxr.mozilla.org/mozilla-central/source/layout/base/nsPresShell.cpp#7173 according to Boris, 0 != mDirtyRoots.Length().

Comment 12

[Joel Reymont (:joelr)]

Attachment: PresShell::ProcessReflowCommands call sites, with thread id

Comment 13

[Joel Reymont (:joelr)]

Attachment: Simplified script to print process reflow call sites and count

Comment 14

[Joel Reymont (:joelr)]

Attachment: Shows when ProcessReflowCommands is actually doing work. Uses a custom dtrace probe.

Just 14 times out of 53-64.

Comment 15

[Joel Reymont (:joelr)]

Attachment: Use custom probe

Comment 16

[Joel Reymont (:joelr)]

Attachment: dtrace usdt probe triggered when ProcessReflowCommands is doing work

Comment 17

[Joel Reymont (:joelr)]

Attachment: Call sites for ProcessReflowCommands that applies to XUL docs and where work happens

Uses custom probes that mark beginning and end of work.

Comment 18

[Joel Reymont (:joelr)]

Attachment: Source code mods to add XUL reflow USDT probes

Comment 19

[Joel Reymont (:joelr)]

Attachment: XUL reflows when loading the "Getting involved..."

Now with individual timings above each stack trace, as well as the matching number of roots.

Comment 20

[Joel Reymont (:joelr)]

Attachment: Now with # of roots as first argument

Comment 21

[Joel Reymont (:joelr)]

Attachment: dtrace script to time XUL reflows and print the # of roots

Comment 22

[Joel Reymont (:joelr)]

Attachment: XUL reflows when loading a blank page

Comment 23

[Joel Reymont (:joelr)]

Why are there 25 reflows for the "Getting involved" page and just 11 reflows for a blank page?

Comment 24

[Boris Zbarsky [:bzbarsky]]

Excellent question!  Want to investigate that?  Figure out which stacks are "extra"?

Comment 25

[Joel Reymont (:joelr)]

I'm investigating already. I will try to either add more static probes or make reflow data structures available to DTrace. I want to know what text is being set, what objects are being used, etc.

Comment 26

[Boris Zbarsky [:bzbarsky]]

I was thinking more comparing the two logs and seeing what the differences are...  But sure, whichever way works.

Comment 27

[Sylvestre Ledru [:Sylvestre]]

Moving to p3 because no activity for at least 24 weeks.

Comment 28

[BugBot [:suhaib / :marco/ :calixte]]

The bug assignee is inactive on Bugzilla, so the assignee is being reset.