Closing windows is slow in RDF [WAS: Closing windows is slow destroying JS contexts and in RDF]

RESOLVED FIXED in mozilla1.0

Status

()

Core
RDF
--
major
RESOLVED FIXED
17 years ago
4 years ago

People

(Reporter: jesup, Assigned: Robert John Churchill)

Tracking

({perf, testcase})

Trunk
mozilla1.0
x86
All
perf, testcase
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(6 attachments, 2 obsolete attachments)

(Reporter)

Description

17 years ago
We spend a LOT of CPU time closing windows, even about:blank windows.

I'll attach an HTML from bug 49141 (open window performance).  Browser to the
testcase, then select Quit.  Note that the windows take a fair while to go away
one at a time.  I'll attach a jprof of this; 75% is spent destroying the
WebShell, 2/3 of that time is spent in destroying JS contexts, 3/4 of that in
ForceGC.  The other 25% (!) is spent in RDFContainerImpl::Renumber -> Assert ->
nsXULTemplateBuilder::Propogate.

The worst offender:

62  154 js_Mark
    139 XPC_WN_Shared_Mark(JSContext *, JSObject *, void *)
    105 XPC_WN_Shared_Proto_Mark(JSContext *, JSObject *, void *)
     37 fun_mark
     19 js_MarkGCThing
      4 script_mark
      1 js_Mark
      1 js_GetGCThingFlags
      1 _init
(Reporter)

Updated

17 years ago
Keywords: perf, testcase
(Reporter)

Comment 1

17 years ago
Created attachment 52992 [details]
Opens 20 about:blank windows, from bug 49141
(Reporter)

Comment 2

17 years ago
Created attachment 52993 [details]
jprof of quit with 20 about:blank windows open
I think this is a dup of bug 66381.  Shaver, what do you think?

/be
I think that every time I look at 66381 I feel small and guilty.  If someone can
point me at a footprint win from better GC scheduling, I'll see if I can get
chofmann to let me run at it in the near term.

(But yeah, I think this is very much related.)

Comment 5

17 years ago
We should file a separate bug on the RDF stuff. I'd bet a donut that the problem
is updating the ``Tasks'' menu as each window closes. (The 20th window to close
updates each menu in the 19 remaining windows; the 19th window to close updates
each menu in 18 remaining windows; the 18th window to close updates each menu in
the 17 remaining windows; etc...)

Comment 6

17 years ago
From above, it looks like bug 66381 covers the JS Engine side of this.

I'd like to keep this bug open for the RDF issue; therefore reassigning
to XP Toolkit/Widgets and resummarizing.
Assignee: rogerl → hyatt
Component: Javascript Engine → XP Toolkit/Widgets
QA Contact: pschwartau → jrgm
Summary: Closing windows is slow destroying JS contexts and in RDF → Closing windows is slow in RDF [WAS: Closing windows is slow destroying JS contexts and in RDF]
(Reporter)

Comment 7

17 years ago
The JS engine part is not a dup of bug 66381.  Yes, we spend a lot of time in
Mark, but the real problem is that destroying the contexts is expensive - i.e.
there's a lot of cleanup/GC to do in total.  Bug 66381 is about incremental GC,
which doesn't help us much in this case I believe (except maybe by pushing some
Close overhead onto Open, which is already too slow).  Perhaps incremental will 
produce less total overhead, but that seems unlikely, especially in this case.

FYI, 21 hits (5%) is js_LiveContext alone.  js_MarkScript had 3% direct hits
alone.

We should either open a new bug for RDF (as waterson indicated) or for the 3/4
of the CPU time that's used in destroying the WebShell (which was the main focus
of this bug).  Or open both and make this a meta-bug for window close.
(Reporter)

Comment 8

17 years ago
The checkin for reducing IndexOf() usage in FilterInstantiations by tingley for
bug 104328 has helped.  In a jprof (to be posted), the overhead for
nsRDFConMemberTestNode::FilterInstantiations calls to ::IndexOf() dropped by
about 80% (50 hits to 11).  Overall number of hits (roughly CPU used and closely
related to wallclock time) dropped by close to 10%, basically all from this
change.  I do note a strong differential in the speed of closing a window with
20 open, and in closing a window with (say) 2 open.  We do have at least one
factor that's O(N^2) or O(NlogN) or some such.  Perhaps the Tasks menu, but
maybe there are more.
(Reporter)

Comment 9

17 years ago
Created attachment 53948 [details]
Updated profile after fix to 104328
(Reporter)

Comment 10

17 years ago
RDF is no longer a major issue here; the sore thumb is destroying JS contexts;
retargeting to that, reassigning to Shaver.  There may be some other areas of
XUL/RDF/etc that can help; however the overhead for RDF is down from ~25% to
about 14%, while js_GC is up from 46% to 53% (of what's left; it takes exactly
the same amount of time).

I do _not_ think this is the same as bug 66381, though it's possible a fix to
66381 might help or remove this issue.  There may be fixes/hacks that could help
with this though even if 66381 can't be handled (yet).
Assignee: hyatt → shaver
Component: XP Toolkit/Widgets → Javascript Engine
Summary: Closing windows is slow in RDF [WAS: Closing windows is slow destroying JS contexts and in RDF] → Closing windows is slow destroying JS contexts [WAS: Closing windows is slow in RDF]

Comment 11

17 years ago
It looks like RDF OnAssert() still accounts for about 52 stacks (F+D) out of
392, or 13%. So, it's not _completely_ off the radar. But it's not the big fish
anymore. (Or am I just reading this wrong?)

Comment 12

17 years ago
I agree, there is still more work to be done here -- I had begun to look into
this when I was sidetracked by the IndexOf() problem.  

It looks like in this case we're spending a lot of time in container
renumbering.  I don't remember how this works off the top of my head, but the
experimental stuff I had to speed up sequence building may be useful here.
Summary: Closing windows is slow destroying JS contexts [WAS: Closing windows is slow in RDF] → Closing windows is slow in RDF [WAS: Closing windows is slow destroying JS contexts and in RDF]

Updated

17 years ago
Blocks: 91351
Well, if this is a meta-bug, I just did a profile of closing a bunch of windows
(I forget how many, probably somewhere around 15 so the O(N^2) problems don't
kick in too much and we get some realistic numbers).

I saw (with each number excluding what's included in all previous ones where it
would be possible for something to be counted twice):

  49% of the time within js_GC
  18% of the time spent in nsWindowMediator::UnregisterWindow (in N^2 RDF stuff)
  6.2% of the time spent in the |SetDocument| calls on the content model (some
of them going through XBL and invoving some XBL shutdown)
  8.7% of the time in the |Destroy| methods on the frame tree, although 4.1% of
the total was in nsWindow::DestroyNative and almost all of that was in the X
server call in DestroyNativeChildren
  2.8% of the total in JS_ClearScope
  4.3% of the total writing the bookmarks file to disk
  10% of the total in other miscellaneous places

(that should add up to 100%)
I shouldn't blame js_GC for all of that 49%.  Some of the total was finalization
of objects that were freed by the GC.  2.6% was the destructors of
nsHTMLDocument and the content nodes within it.  0.3% was other destructors.  4%
was within js_FinalizeObject, which was entirely JS objects, since the XPC
wrapped objects are released from the DOMGCCallback.  (I guess I should mention
that all the browser windows I opened contained the page
http://www.people.fas.harvard.edu/~dbaron/ in the window.)

Updated

17 years ago
Keywords: mozilla0.9.9
(Assignee)

Comment 16

17 years ago
Created attachment 70799 [details] [diff] [review]
Patch to filter out RDF SEQ renumbering

Anyone care to test this patch? Getting some hard performance #s would be nice.


It basically adds some magic to filter out RDF SEQ renumbering noise in
nsWindowMediator. By my count, it filtered out 462 RDF notifications when
testing with the test (first attachment on this bug) that opens 20 about:blank
windows, then quitting.

(Note: The diff looks bigger than it really is, as I moved all the code in the
.h file into the .cpp file [Hate that!] and gave the code some formatting
cleanup.)
(Assignee)

Comment 17

17 years ago
Created attachment 70800 [details] [diff] [review]
Patch to filter out RDF SEQ renumbering

Same patch sans tabs (beat your editor into submission; I did.)
Attachment #70799 - Attachment is obsolete: true
(Assignee)

Comment 18

17 years ago
In case anyone is curious where the number 462 comes from, here's the math:

X = 21 windows (1st browser window + 20 more about:blank windows)
Y = 21 RDF_nextVal decrements as windows are closed during Quit
(X^2) + Y = 462

Comment 19

17 years ago
Created attachment 70886 [details]
**** test for window closing time

I took a lame stab at measuring for window closing time. It spits out numbers, 

but I'm not convinced that this is really doing the right thing. But at any
rate, it does show about ~4% improvement in window closing on Linux, although
the gain seems to evaporate the longer the test continues to run (and the more
bloaty the app becomes). 

(Side note: on NT based systems, I think, if we're keeping the
heap-minimize-on-window-close, that we should consider that idea of a timer
to try to coalesce those systems calls. I think we may be blowing off time when
closing a number of windows consecutive (which I do in my normal browsing
usage, not just in this artificial test)).

Comment 20

17 years ago
I just glanced at this briefly, but I'm not sure if this really solves the problem.

RemoveAndUpdateSynthetics is still doing a lot of damage here:
+  mContainer->RemoveElement(winNode, PR_TRUE);

This causes a huge renumbering behind-the-scenes in the container code, as every
container element after winNode has its nextVal decremented by one.  This causes
a flood of observer calls and the content-building code chewing on its cheeks
for a while.

Is there something in the patch to prevent this that I just don't see?

Updated

17 years ago
Keywords: mozilla1.0+
(Assignee)

Comment 21

17 years ago
Chase: with these changes, the WindowMediator becomes an observer to the
internal RDF_NextVal renumbering changes:
    +    rv = mInner->AddObserver(this);

and then can batch-out the effects so that the XUL Template builder doesn't see
them.
(Assignee)

Comment 22

17 years ago
Created attachment 72176 [details] [diff] [review]
Same patch re: RDF_SEQ, but make synthetic hack smarter (less notificationa)

Same patch as before regarding RDF_SEQ renumbering filtering, but with a slight
change to make the synthetic notifications smarter (only need to update
synthetics which changed due to a renumbering cycle).
Attachment #70800 - Attachment is obsolete: true

Comment 23

17 years ago
Wow.  To get some idea of the magnitude of the improvement, I added an autotimer
to nsRDFContainer::RemoveElement.  Then I opened 21 blank windows as per the
attachment, tiled them so only title bars were visible (window 1 furthest back),
then click-closed them in order from 1 to 21.  Closing the lowest number first
should maximize the renumbering hit.

Comparing the times shows an enormous improvement.

Without patch:
1024[809e468]: RemoveElement: took 391573 tics
1024[809e468]: RemoveElement: took 374323 tics
1024[809e468]: RemoveElement: took 332701 tics
1024[809e468]: RemoveElement: took 308043 tics
1024[809e468]: RemoveElement: took 281935 tics
1024[809e468]: RemoveElement: took 240681 tics
1024[809e468]: RemoveElement: took 214386 tics
1024[809e468]: RemoveElement: took 196059 tics
1024[809e468]: RemoveElement: took 165845 tics
1024[809e468]: RemoveElement: took 131937 tics
1024[809e468]: RemoveElement: took 106793 tics
1024[809e468]: RemoveElement: took 99471 tics
1024[809e468]: RemoveElement: took 74750 tics
1024[809e468]: RemoveElement: took 56163 tics
1024[809e468]: RemoveElement: took 43176 tics
1024[809e468]: RemoveElement: took 28761 tics
1024[809e468]: RemoveElement: took 21433 tics
1024[809e468]: RemoveElement: took 12462 tics
1024[809e468]: RemoveElement: took 6547 tics
1024[809e468]: RemoveElement: took 2832 tics
1024[809e468]: RemoveElement: took 3077 tics

After patch:
1024[809e468]: RemoveElement: took 1992 tics
1024[809e468]: RemoveElement: took 1891 tics
1024[809e468]: RemoveElement: took 1830 tics
1024[809e468]: RemoveElement: took 1698 tics
1024[809e468]: RemoveElement: took 1632 tics
1024[809e468]: RemoveElement: took 3704 tics
1024[809e468]: RemoveElement: took 1493 tics
1024[809e468]: RemoveElement: took 1362 tics
1024[809e468]: RemoveElement: took 3447 tics
1024[809e468]: RemoveElement: took 1504 tics
1024[809e468]: RemoveElement: took 1323 tics
1024[809e468]: RemoveElement: took 1018 tics
1024[809e468]: RemoveElement: took 3228 tics
1024[809e468]: RemoveElement: took 847 tics
1024[809e468]: RemoveElement: took 806 tics
1024[809e468]: RemoveElement: took 700 tics
1024[809e468]: RemoveElement: took 613 tics
1024[809e468]: RemoveElement: took 532 tics
1024[809e468]: RemoveElement: took 450 tics
1024[809e468]: RemoveElement: took 368 tics
1024[809e468]: RemoveElement: took 281 tics

The difference is very noticeable to the user.

I still need to go through the code in detail, but in terms of rough perf
estimates, this looks like a big win.
(Reporter)

Comment 24

17 years ago
Could you post a patch diffed with -u -w?  All the indentation/tab/etc fixes
make it hard to review.

I like the de-tabification, but there appear still to be tabs in some of the
lines you modified.

Is there a reason for asserting style over function declarations?  (type on a
separate line)  Not that I'm complaining per se.

I love the perf win!
(Assignee)

Comment 25

17 years ago
Created attachment 72848 [details] [diff] [review]
Same patch as previous but "diff -w -u4"

"diff -w -u4" for rjesup

Comment 26

17 years ago
[changing component/assignee based on current activity]
Assignee: shaver → rjc
Component: JavaScript Engine → RDF

Comment 27

17 years ago
a good one for speeding up window close -->  nsbeta1
Keywords: nsbeta1
(Assignee)

Updated

17 years ago
Target Milestone: --- → mozilla1.0
(Assignee)

Updated

17 years ago
Status: NEW → ASSIGNED
Comment on attachment 72848 [details] [diff] [review]
Same patch as previous but "diff -w -u4"

[s]r=ben
Attachment #72848 - Flags: superreview+
(Assignee)

Comment 29

17 years ago
Verbal r=danm

Comment 30

17 years ago
Comment on attachment 72848 [details] [diff] [review]
Same patch as previous but "diff -w -u4"

a=asa (on behalf of drivers) for checkin to the 1.0 trunk
Attachment #72848 - Flags: approval+
(Assignee)

Comment 31

17 years ago
Marking fixed.
Status: ASSIGNED → RESOLVED
Last Resolved: 17 years ago
Resolution: --- → FIXED

Comment 32

17 years ago
It looks like the leak jump was probably this checkin. I filed bug 129794.
You need to log in before you can comment on or make changes to this bug.