Open Bug 645678 Opened 11 years ago Updated 8 years ago

GC Delay is increased by certain extensions right from launch

Categories

(Core :: General, defect)

x86
Windows 7
defect
Not set
normal

Tracking

()

People

(Reporter: danialhorton, Unassigned)

References

()

Details

(Keywords: perf)

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.
Status: UNCONFIRMED → NEW
Ever confirmed: true
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.
Keywords: perf
You need to log in before you can comment on or make changes to this bug.