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

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.)

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...)

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.

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.

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.

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).

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?)

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.

See also bug 28639 and bug 39742.

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.)

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.)

Same patch sans tabs (beat your editor into submission; I did.)

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

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)).

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?

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.

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).

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.

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!

"diff -w -u4" for rjesup

[changing component/assignee based on current activity]

a good one for speeding up window close --> nsbeta1

Comment on attachment 72848 [details] [diff] [review] Same patch as previous but "diff -w -u4" [s]r=ben

Verbal r=danm

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

Marking fixed.

It looks like the leak jump was probably this checkin. I filed bug 129794.