User-Agent: Mozilla/5.0 (Windows; U; Windows NT 6.1; en-GB; rv:1.9.2.16) Gecko/20110319 Firefox/3.6.16 GTB7.1 Build Identifier: I was in contact with some mozdevs back in january about this issue, and they got me to test a GC Stats build (unfortunately they never got back to me about getting a build again as i lost it during a drive transfer) Anyway, it seems there are a few notable extensions that severely impact the GC Delay when installed end enabled, and it seems the devs of those extensions aren't likely to touch the issue (likely due to a lack of understanding of the matter). Anyhow, the extensions worst off in my testing of the delay (using the gc delay dial on http://hacks.mozilla.org/2010/01/javascript-speedups-in-firefox-3-6/) and otherwise generally feeling the difference (through hiccups and stutters/skipping) are Adblock plus, Google toolbar, Ebay Toolbar and session manager (though session manager appears to be ok in Fx4) Using the dial i measured these stats the entire time i was running these extensions individually Ebay sidebar - increases the length by 7ms (24ms total) Google Toolbar - increases the length by 10-12ms (27-29ms total) Adblock Plus - Increases the length by 10-15ms (30-31ms total) Session Manager - Increases the length by 6-10ms (22-25 total on 3.6.x) (15-19ms on Fx4). Some of my other extensions start with a high delay (27ish all up) but settle down into around 17ms average after the first couple of cycles. This issue is basically to get feedback from Mozdevs on the potential reasons for my findings and helping the ExtDevs to apply any possible fixes. Reproducible: Always Steps to Reproduce: 1. Install one of the specified extensions 2. Browse around some animated gif or flash enabled sites 3. use the GC Delay metre on http://hacks.mozilla.org/2010/01/javascript-speedups-in-firefox-3-6/ Actual Results: GC Delay can easily be put over 40ms by running a combination of these extensions and skip during animated content playback. Expected Results: Smoothness would be nice :D I know this is an issue caused by certain extensions but the underlying cause is in developers not having a clear understanding of how to minimise the impact of their extension(s) on the firefox garbage collection.

Anreas, your intern might be interested in this!

ahaha, it was you, Andreas and Gregor that i was directed to iirc. I should've made an artifact for the issue then so it could be tracked better but i had a overdue transfer of my hardware to a new case that i had been putting off and finally decided to do it that week. "To: Roc Cc: Danial Horton ; Gregor Wagner ; Boris Zbarsky Subject: Re: extensions vs garbage collector I don't think anyone has looked at this systematically. We should first try to figure out what part of GC (or CC, which is more likely the source here IMO) is affected. Gregor has some define that outputs extra timing info during GC. We should start with that. Danial, if we give you some instructions how to collect more precise GC statistics, do you want to give that a try?" I did initially get the GC stats build from Gregor, but It went missing when i replaced my downloads drive :\

ccing Gregor too.

(In reply to comment #0) > I know this is an issue caused by certain extensions but the underlying cause > is in developers not having a clear understanding of how to minimise the impact > of their extension(s) on the firefox garbage collection. I would certainly be interested in knowing how an extension (and Adblock Plus in particular) can have an influence on GC delays. This is the first time I hear about it.

It was the GC test that i noticed it in, Andrea's is probably right about it being CC, but i assure you the findings were reproduced in a fresh profile after i noticed then in my usual profile. The reproduction with ABP was with a subscription however, it is not reproducible without a ad database so i expect where ABP is concerned its part of having all those subscription strings loaded. my original mail to Rob(ROC) "Ebay sidebar - increases the length by 7ms Google Toolbar - increases the length by 10-12ms Adblock Plus - Increases the length by 10-15ms Session Manager - Increases the length by 6-10ms with no extensions loaded, my average is 18ms, with only these loaded it peaks at 45ms" Had to sort through a few thousand sent mails to find that.

finding the reasons for this would likely be only worth it for short term anyway, the compartmentalised GC might stop this from being so obvious to those of us sensitive to skippy animations.

Wladimir, the simplest way an extension can affect the length of a gc delay is by creating a lot of objects. The bigger the heap, the longer it takes to walk it. If the extension causes a lot of object churn (so destroys objects in addition to creating them), you also have to finalize all those objects. The simplest way an extension can affect the length of the cc delay is by effectively leaking DOM nodes (holding on to them after the relevant DOM document has been unloaded). We optimize cc traversals to shortcircuit for nodes that are in a DOM tree, but if you drag around a bunch of disconnected nodes, that will cost. For anyone who cares: In Firefox 4, you can flip the boolean preference "javascript.options.mem.log" to true in about:config to have us log gc and cc times and some additional information about how much is being collected to the error console. It might be worth seeing whether the extensions above increase gc or cc times, for a start.

just thought i should mention the testing of my other extensions, and surprisingly the ones i most expected to affect it actually didn't. All these results are in Fx4, and reproduced in 3.6.12 (at the time) i've marked those where the results differed in the older browser. The first value is the minimum / settled in result after a few moments when the cycle collector does its first couple of runs i would assume, the second value is max, most usually right after startup. 13-15ms unloaded Adblock Plus 30-31ms Add-on Reporter 15-18ms BBCode 16-18ms Cache Status 18-21ms Console 2 14-23ms Default Full Zoom 13-16ms DivX HiQ 17-20ms DivX Html5 video 16-19ms Download Status Bar 16-18ms Element Hiding Helper 15ms Element Properties 16ms English Australian Dictionary 15-17ms Facebook chat notifications 15-17ms Fasterfox Lite 12-17ms Flashgot 15-17ms Flashblock 15-19ms Google Toolbar 27-29ms IE Tab Plus 14-17ms Image Toolbar 14-17ms Image Zoom 14-17ms Java Console 15-17ms Logitech Device Detection 14-17ms Netusage extension 14-17ms (themes don't effect delay) OpenSearchFox 14-19ms OptimizeGoogle 17-24ms (this one starts high and drops to normal and stays there) Personas 14-18ms Ramback 13-17ms SQLite Manager 14ms SQLite Optimizer 14-19ms Search Site 13-23ms Session Manager 15-19ms (Results in Fx4)(22-25 total on 3.6.x) Status-4-evar 15-17ms (tested in Fx4) StatusbarEx 16-21ms TabMix Plus 20ms Update Channel Selector 16-19ms User Agent Switcher 16-20 Vacuum Places Improved 16-21ms Veoh Extension 17ms Xul Profiler I could not get an adequate measurement of this one, it was actually the worst extension whether run with the others or not, it immediately added 20+MS to the results I'll enable ABP in a new profile and enable that setting Boris

Some results on my Firefox 4.0, Windows 7 64-bit (32-bit Firefox): After 24 hours with a bunch of open tabs: CC: collected: 6 (6 waiting for GC), suspected: 359, duration: 80 ms. GC: full, duration: 113 ms. Disabled all extensions, restarted, let it settle for a few minutes: CC: collected: 0 (0 waiting for GC), suspected: 260, duration: 7 ms. GC: full, duration: 22 ms. Re-enabled all extensions, restarted, let it settle for a few minutes: CC: collected: 0 (0 waiting for GC), suspected: 331, duration: 15 ms. GC: full, duration: 52 ms. I have 19 extensions installed. So just having them installed does add to GC time, but the worse issue is that the GC/CC durations grow over time.

Alright, in ABP's case it is definitely GC, Went from 10-12ms to 18-19ms in Fx4, that is reduced a bit from 3.6.x though

i take that back actually. the results increased again to 24ms with a subscription enabled in ABP after letting it settle in and then CC increased to 9ms (was 3ms prior)

Roman, thats not unusual, the more in use (not allocated, if i read correctly) memory the longer cycles will take to trace it all. i think part of the benefits of compartmentalised GC was concurrent, generational and partial collection? (not sure on the partial!)

Some results (on a Mac), order is oldest to newest. These were taken after the browser had been used for a few hours. Before copying these stats I had closed all windows and cleared all history and cache except cookies. Opened a new window: CC timestamp: 1301347454708036, collected: 5662 (5662 waiting for GC), suspected: 5771, duration: 282 ms. GC mode: full, timestamp: 1301347453540811, duration: 151 ms. Let it settle: CC timestamp: 1301347464087034, collected: 0 (0 waiting for GC), suspected: 373, duration: 236 ms. GC mode: full, timestamp: 1301347458849302, duration: 140 ms. Navigated to new page: CC timestamp: 1301347513612811, collected: 20 (20 waiting for GC), suspected: 1904, duration: 241 ms. GC mode: full, timestamp: 1301347512438588, duration: 139 ms. Mem stats: malloc/allocated & malloc/zone0/committed: ~224MB malloc/mapped & malloc/zone0/allocated: ~300MB firefox-bin: ~415MB plugin-container (flash): ~180MB I don't usually notice any slowdowns until firefox-bin is stuck above 560 MB or so. Will check these stats the next time the memory usage climbs to that level. Extensions, latest (dev) version available: AdBlock DownThemAll Flashgot NoScript Scriptish Tab Mix Plus

While writing up that comment I got this (oldest to newest): 8 CC - 1 GC - 1 CC - 1 GC - 8 CC. Each of the 8 CC's looked like this, except the first in each set which had a suspected value of around 400-500. CC timestamp: 1301348272056317, collected: 0 (0 waiting for GC), suspected: 1109, duration: 264 ms. Suspected was between 1000 and 1100 in all of them, except the first which was around 420.

> CC timestamp: 1301348272056317, collected: 0 (0 waiting for GC), suspected: > 1109, duration: 264 ms. Yeah, so what that's telling me is that someone is keeping a bunch of DOM objects (probably) alive but not inside documents and we're taking a lot of time traversing them during cycle-collection....

(In reply to comment #7) > The simplest way an extension can affect the length of the cc delay is by > effectively leaking DOM nodes (holding on to them after the relevant DOM > document has been unloaded). That would be the redirect detection hack in Adblock Plus. I could confirm that it causes CC to run twice by attaching data from the previous content policy call (including a DOM node) to the corresponding HTTP channel (via nsIWritablePropertyBag). This data can then be used in onChannelRedirect to get the required context info. Unfortunately, there is no "this channel is done" notification that would allow removing data from the channel. I tried http-on-examine-response and http-on-examine-cached-response notifications but they are triggered before redirect processing. And since redirect processing is now asynchronous I don't know how long I need to wait after http-on-examine-response until it is clear that the data will no longer be used.

> attaching data from the previous content policy call (including a DOM node) to > the corresponding HTTP channel Uh... You're having the channel hold a strong ref to the DOM node? If you're doing that, you're almost certainly just leaking the world for tab lifetime (specifically, the new document holds a ref to the channel it was loaded from, which holds a ref to the DOM node, which is likely keeping its owner document alive, which keeps alive the channel _that_ was loaded from, etc, so that all the documents ever loaded in that tab are alive until the tab gets closed). Worse yet, even if you close the tab you might leak permanently: channels don't participate in cycle collection, so if there's a ref through the node you stuck on the channel to the document that was loaded from the channel you will get a permanent leak. > Unfortunately, there is no "this channel is done" notification And of course you filed a bug on that instead of just leaking the world, right? For what it's worth, there is such a notification as far as I can see: a combination of onChannelRedirect to know when a new channel is being switched to and onStartRequest to know when there will be no more redirects. Please feel free to mail me to discuss the details!

Please retest with https://adblockplus.org/devbuilds/adblockplus/adblockplus-1.3.6a.2946.xpi - this issue should be fixed. I am using nsITraceableChannel to clean up now, with the unfortunate side-effect that redirect blocking is broken in Fennec 4.0 (due to bug 646373).

(In reply to comment #18) > Please retest with > https://adblockplus.org/devbuilds/adblockplus/adblockplus-1.3.6a.2946.xpi - > this issue should be fixed. I am using nsITraceableChannel to clean up now, > with the unfortunate side-effect that redirect blocking is broken in Fennec 4.0 > (due to bug 646373). Testing this: http://hacks.mozilla.org/2010/01/javascript-speedups-in-firefox-3-6/ Frame delay: 17ms GC Delay: First 47ms, then 35ms, then 30ms Compared to running the same on the 28th of March Frame delay: 5ms GC Delay: ~20-25ms Error console (oldest to newest): CC timestamp: 1301485224274593, collected: 0 (0 waiting for GC), suspected: 247, duration: 22 ms. CC timestamp: 1301485273844285, collected: 0 (0 waiting for GC), suspected: 1130, duration: 25 ms. CC timestamp: 1301485320443862, collected: 0 (0 waiting for GC), suspected: 1156, duration: 24 ms. Browser has been running for less than 5 minutes at the moment.

This just popped up: Error: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIStreamListener.onStartRequest]" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: chrome://adblockplus-modules/content/Utils.jsm :: <TOP_LEVEL> :: line 663" data: no] Source File: chrome://adblockplus-modules/content/Utils.jsm Line: 663

The exception doesn't mean anything - it is one that is usually being swallowed, it only became visible because now there is JavaScript on the stack. As to your results, I'm not sure how much a run with half a dozen extensions means, especially when performed several days after the comparison run (as opposed to minutes). Anyway, my question was mainly directed to Danial Horton.

Never mind, I can see that the delays caused by Adblock Plus in Firefox 3.6 are basically the same - while in Firefox 4 they were almost beyond measurable from the start. So there are two issues here. First was keeping DOM nodes alive which in this test caused delays of 2-3 ms (that's what I've seen in Firefox 4 and fixed now). The other was having many objects in memory - that's Adblock Plus filter data which is still causing significant delays in Firefox 3.6 (proportional to the number of filters) while having basically no impact in Firefox 4 (thanks to compartments I guess). I guess I'll just leave that second issue alone unless somebody has a great suggestion on minimizing this impact.

re: comment 16: > And since redirect processing is now asynchronous I don't know how long I need > to wait after http-on-examine-response until it is clear that the data will no > longer be used. Wladimir: We now have nsIRedirectResultListener, which will tell you the result of a redirect (i.e. whether it went through, or got cancelled and the old channel is being used). Is that enough for your purposes?

Hold that thought: I just realized that nsIRedirectResultListener is not supported right now on the child process. Filed bug 646774.

@Jason: Neither are http-on-examine-response/http-on-examine-cached-response supported on the child process so it wouldn't help much. The current solution with nsITraceableChannel is more reliable anyway so I think that I'll stick with it - now that only needs to start working with e10s.