Open Bug 514275 Opened 11 years ago Updated 1 year ago

XUL stuff reflows too often on startup

Categories

(Core :: XUL, defect, P3)

defect

Tracking

()

People

(Reporter: taras.mozilla, Assigned: joelr)

References

(Blocks 1 open bug)

Details

(Whiteboard: [ts])

Attachments

(4 files, 10 obsolete files)

32.00 KB, text/plain
Details
1.60 KB, text/plain
Details
937 bytes, text/plain
Details
15.55 KB, text/plain
Details
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.
Forgot to mention, looking at callers of ProcessReflowCallbacks() is also important... It processes things that are unsafe during reflow and possibly causes bonus reflows
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
Whiteboard: [ts]
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
What is a reflow pass? Where does it start and end?
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
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?
OS: Linux → All
Hardware: x86 → All
> 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 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.
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().
Attachment #399191 - Attachment is obsolete: true
Attachment #399192 - Attachment is obsolete: true
Just 14 times out of 53-64.
Attachment #399194 - Attachment is obsolete: true
Attachment #399196 - Attachment is obsolete: true
Attached file Use custom probe (obsolete) —
Attachment #399197 - Attachment is obsolete: true
Attachment #399216 - Attachment mime type: application/octet-stream → text/plain
Uses custom probes that mark beginning and end of work.
Attachment #399214 - Attachment is obsolete: true
Attachment #399215 - Attachment is obsolete: true
Attachment #399216 - Attachment is obsolete: true
Now with individual timings above each stack trace, as well as the matching number of roots.
Attachment #399233 - Attachment is obsolete: true
Attachment #399238 - Attachment is obsolete: true
Why are there 25 reflows for the "Getting involved" page and just 11 reflows for a blank page?
Excellent question!  Want to investigate that?  Figure out which stacks are "extra"?
Assignee: nobody → 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.
I was thinking more comparing the two logs and seeing what the differences are...  But sure, whichever way works.
Priority: -- → P1
Blocks: 447581
Component: XUL Widgets → XUL
Product: Toolkit → Core
QA Contact: xul.widgets → xptoolkit.widgets
Moving to p3 because no activity for at least 24 weeks.
Priority: P1 → P3
You need to log in before you can comment on or make changes to this bug.