During my tests with Bug 608954, I've found first add-on, which causing growing cc time, it's NoScript (current version 2.3.3). Without it cc time is in general 40-70 ms, with it it start from ~200 ms in first hour and now it's ~1000 ms after one day of browsing CC(T+99013.5) collected: 0 (0 waiting for GC), suspected: 327, duration: 1062 ms. GC(T+99027.1) Type:Glob, Total:178,9, Wait:0,2, Mark:141,0, Sweep:35,0, FinObj:4,8, FinStr:0,3, FinScr:0,2, FinShp:5,3, DisCod:1,5, DisAnl:3,0, XPCnct:15,1, Destry:0,1, End:16,5, +Chu:0, -Chu:0, Reason: API CC(T+99029.0) collected: 169 (169 waiting for GC), suspected: 4496, duration: 1078 ms. GC(T+99047.3) Type:Glob, Total:175,3, Wait:0,2, Mark:137,6, Sweep:34,1, FinObj:4,1, FinStr:0,5, FinScr:0,2, FinShp:4,8, DisCod:1,2, DisAnl:3,5, XPCnct:15,6, Destry:0,1, End:18,1, +Chu:0, -Chu:0, Reason:Maybe CC(T+99053.4) collected: 102 (102 waiting for GC), suspected: 467, duration: 1094 ms. about:memory?verbose output attached as file. Unfortunately, when I try to make cc dump I get crash, filled separate Bug 710169 for it

Did closing tabs improve the CC times at all? That looks like a fair amount of XPConnect in there, I don't know if that is related.

No, it isn't, that times were taken with only two windows left opened, each with one tab. During work time there was spikes for ~15 tabs and 20-30 windows

It doesn't look like you have any zombie compartments, but heap-unclassified is fairly large. Maybe the addon is leaking in a way that hits the cycle collector hard.

ccing Giorgio.

I've updated noscript to latest nightly 2.2.4rc2, cc times become grow slower, now it takes two days to reach >1000 ms, current stat: GC(T+172258.5) Type:Glob, Total:156,6, Wait:0,2, Mark:122,7, Sweep:31,3, FinObj:3,3, FinStr:0,2, FinScr:0,2, FinShp:5,0, DisCod:1,2, DisAnl:2,8, XPCnct:14,6, Destry:0,1, End:16,1, +Chu:0, -Chu:0, Reason: API CC(T+172264.6) collected: 223 (223 waiting for GC), suspected: 454, duration: 1110 ms. GC(T+172283.7) Type:Glob, Total:200,1, Wait:0,2, Mark:169,1, Sweep:28,9, FinObj:3,2, FinStr:0,1, FinScr:0,2, FinShp:4,9, DisCod:1,1, DisAnl:2,0, XPCnct:13,1, Destry:0,3, End:14,3, +Chu:0, -Chu:0, Reason:Maybe CC(T+172289.9) collected: 102 (102 waiting for GC), suspected: 217, duration: 1203 ms. GC(T+172305.0) Type:Glob, Total:193,0, Wait:0,2, Mark:150,3, Sweep:39,0, FinObj:2,7, FinStr:0,1, FinScr:0,2, FinShp:4,9, DisCod:1,3, DisAnl:2,3, XPCnct:14,2, Destry:0,1, End:15,1, +Chu:0, -Chu:0, Reason:Maybe CC(T+172311.1) collected: 102 (102 waiting for GC), suspected: 217, duration: 1094 ms. Now I'll create topic on Noscript forum and wait for landing fix for Bug 709160

Build identifier: Mozilla/5.0 (Windows NT 5.1; rv:11.0a1) Gecko/20111215 Firefox/11.0a1 SeaMonkey/2.8a1 NoScript 2.2.4rc3 CC times: CC(T+278480.4) collected: 153 (153 waiting for GC), suspected: 129, duration: 1031 ms. GC(T+278500.6) Type:Glob, Total:130,6, Wait:0,2, Mark:106,6, Sweep:22,6, FinObj:2,2, FinStr:0,1, FinScr:0,1, FinShp:4,2, DisCod:0,8, DisAnl:1,2, XPCnct:10,8, Destry:0,1, End:11,1, +Chu:0, -Chu:0, Reason:Maybe CC(T+278506.6) collected: 153 (153 waiting for GC), suspected: 191, duration: 1078 ms. CC(T+278514.8) collected: 0 (153 waiting for GC), suspected: 5343, duration: 1047 ms. GC(T+278520.7) Type:Glob, Total:125,4, Wait:0,2, Mark:101,6, Sweep:22,7, FinObj:2,3, FinStr:0,1, FinScr:0,1, FinShp:4,4, DisCod:0,6, DisAnl:1,3, XPCnct:10,7, Destry:0,1, End:10,8, +Chu:0, -Chu:0, Reason:Maybe CC(T+278526.7) collected: 153 (153 waiting for GC), suspected: 255, duration: 1015 ms. GC(T+278541.3) Type:Glob, Total:128,1, Wait:0,3, Mark:102,3, Sweep:24,9, FinObj:2,1, FinStr:0,1, FinScr:0,3, FinShp:4,3, DisCod:0,8, DisAnl:1,1, XPCnct:12,2, Destry:0,1, End:12,4, +Chu:0, -Chu:0, Reason:Maybe about:memory?verbose attached as file. cc heap dump - http://www.cs.iptcom.net/debug/cc-edges-2.7444.zip Hopes this dump helps reveal source of the problem

I'm not sure about what I'm supposed to look for. Is this Seamonkey-specific (i.e. does it happen on Firefox Nightly)? Is this time-bound or stress-bound (i.e. does it happen after two days even if you've got just one page open and idle, or it happens after a certain number of distinct pageviews)? Is there any way to see how memory fragmentation (if this is the culprit) may be related to specific NoScript activities?

(In reply to Giorgio Maone from comment #7) > Is this Seamonkey-specific (i.e. does it happen on Firefox Nightly)? I didn't try to reproduce this on FF yet, was busy a bit, but I'll try during this week > Is this time-bound or stress-bound (i.e. does it happen after two days even > if you've got just one page open and idle, or it happens after a certain > number of distinct pageviews)? It definitely not time-bound, I left browser open on Friday with cc times ~500 ms, today they was at same level. The problem seems related to opening a couple (10-15-20...) windows or tabs in a row, but I don't have 100% guaranteed pages/sites list to easy reproduce issue > Is there any way to see how memory fragmentation (if this is the culprit) > may be related to specific NoScript activities? How can I check/show this?

(In reply to Phoenix from comment #8) > > Is there any way to see how memory fragmentation (if this is the culprit) > > may be related to specific NoScript activities? > How can I check/show this? This question was more for Boris than for you, thanks for the above :)

Managed to reproduce this behavior on FF nightly, get ~ 200 ms cc time in just two iterations. Build: Mozilla/5.0 (Windows NT 5.1; rv:12.0a1) Gecko/20111220 Firefox/12.0a1 Noscript 2.2.4 release Clean profile, only changed settings are browser.link.open_newwindow 2 browser.tabs.opentabfor.middleclick false browser.tabs.warnOnOpen false javascript.options.mem.log true Steps to reproduce: 1. Start Firefox, set needed settings 2. Open http://dynamo.kiev.ua/news/ page, allow scripts for dynamo.kiev.ua only, all other stay blocked. 3. Scroll down to the end of the page and middle click on second page link. 4. In opened window do the same, scroll down, open next page with middle click. 5. Repeat until there 20 or more windows opened. 6. Slowly scroll to the top of the page, as if you reading this news, close window at end, on some pages open one or two news links with middle click, in new window slowly scroll down and close it. 7. When there is only one news window left, open new with about:memory and close last from dynamo.kiev.ua. 8. Open Error console, check cc times On first such run I get such results GC(T+2278.7) Type:Glob, Total:36,9, Wait:0,1, Mark:26,7, Sweep:9,9, FinObj:2,3, FinStr:0,0, FinScr:0,4, FinShp:2,2, DisCod:0,8, DisAnl:0,7, XPCnct:2,3, Destry:0,0, End:2,4, +Chu:0, -Chu:0, Reason: API CC(T+2279.8) collected: 0 (0 waiting for GC), suspected: 134, duration: 140 ms. GC(T+2282.7) Type:Glob, Total:31,9, Wait:0,2, Mark:24,0, Sweep:7,6, FinObj:0,9, FinStr:0,0, FinScr:0,1, FinShp:2,0, DisCod:0,4, DisAnl:0,8, XPCnct:2,3, Destry:0,0, End:2,3, +Chu:0, -Chu:1, Reason: API CC(T+2287.9) collected: 0 (0 waiting for GC), suspected: 88, duration: 125 ms. On second CC(T+3469.5) collected: 1864 (1864 waiting for GC), suspected: 954, duration: 188 ms. GC(T+3473.5) Type:Glob, Total:41,6, Wait:0,1, Mark:28,8, Sweep:12,0, FinObj:2,4, FinStr:0,1, FinScr:0,1, FinShp:2,5, DisCod:0,6, DisAnl:0,8, XPCnct:4,1, Destry:0,0, End:4,5, +Chu:0, -Chu:0, Reason: API CC(T+3478.7) collected: 0 (0 waiting for GC), suspected: 28, duration: 187 ms. GC(T+4145.4) Type:Glob, Total:50,1, Wait:0,1, Mark:32,4, Sweep:16,2, FinObj:3,1, FinStr:0,2, FinScr:0,1, FinShp:3,0, DisCod:0,7, DisAnl:2,9, XPCnct:3,7, Destry:0,0, End:4,7, +Chu:0, -Chu:0, Reason: API Also, there was a couple of such errors, not sure if they are related Timestamp: 21.12.2011 16:31:10 Error: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIXPCComponents_Utils.getWeakReference]" nsresult: "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: chrome://noscript/content/Policy.js :: <TOP_LEVEL> :: line 75" data: no] Source File: chrome://noscript/content/Policy.js Line: 75 cc heap dump after second run attached

Thanks for the detailed steps to reproduce. I'll look into this to see what is happening. I'm going on vacation tomorrow so it may not be for a few weeks. Do those steps cause high CC times only with no script?

Yes, without noscript I get 40-60 ms cc times, they may be higher, when many windows opened, but always drop to low value if I leave only one window

(In reply to Phoenix from comment #10) > Also, there was a couple of such errors, not sure if they are related > Timestamp: 21.12.2011 16:31:10 > Error: [Exception... "Component returned failure code: 0x80004005 > (NS_ERROR_FAILURE) [nsIXPCComponents_Utils.getWeakReference]" nsresult: > "0x80004005 (NS_ERROR_FAILURE)" location: "JS frame :: It's bug 712649. I'm gonna upload in minutes a NoScript version which works around this with null checks, while core devs decide on the API, so you can check if it's actually related.

Please check http://noscript.net/getit#devel

(In reply to Giorgio Maone from comment #14) > Please check http://noscript.net/getit#devel Retested, same situation, after first test run ff+noscript CC(T+10123.3) collected: 38 (38 waiting for GC), suspected: 179, duration: 156 ms. Seamonkey without noscript in same conditions CC(T+22929.7) collected: 0 (0 waiting for GC), suspected: 42, duration: 31 ms.

I strongly suspect bug 646575. At least, I cannot reproduce if I run the following code in the console before starting: Components.utils.getGlobalForObject(top.opener.noscriptOverlay.ns).eval( "ScriptSurrogate._es = ScriptSurrogate._es || ScriptSurrogate.executeSandbox; ScriptSurrogate.executeSandbox = ScriptSurrogate.execute" ); (Otherwise every page loaded in a frame causes NoScript to use one or more throw-away sandboxes to run Script Surrogates)

Correction: in this very case, the sandbox creation / usage / (buggy?) disposal is triggered by the Google Analytics external script attempting to load and being replaced by NoScript's surrogate, rather than by subdocument creation. I've noticed using document.nodePrincipal instead of window as the 1st Sandbox constructor parameter and recycling the object passed as the 2nd parameter *seems* to mitigate the issue (not sure which of the two changes is responsible). Can you confirm by testing 2.2.5rc3 from http://noscript.net/getit#devel , or is it just an impression of mine?

(In reply to Giorgio Maone from comment #17) > Can you confirm by testing 2.2.5rc3 from http://noscript.net/getit#devel , > or is it just an impression of mine? Sorry for delay, just finished tests, no change for me, three test runs CC(T+254.3) collected: 0 (0 waiting for GC), suspected: 99, duration: 93 ms. CC(T+381.5) collected: 0 (0 waiting for GC), suspected: 66, duration: 172 ms. CC(T+459.2) collected: 0 (0 waiting for GC), suspected: 135, duration: 266 ms. Nightly: Mozilla/5.0 (Windows NT 5.1; rv:12.0a1) Gecko/20111228 Firefox/12.0a1

Hi Phoenix, sorry for the delay here. We just landed some cycle collector improvements to Nightly (starting today), so I'd be interested if you are still seeing the problem with the very latest version of Nightly. If so, maybe we can figure out what the CC is doing that it shouldn't.

If you do reproduce it, if you could follow the instructions on this page: https://wiki.mozilla.org/Performance:Leak_Tools#Cycle_collector_heap_dump and run the command in the third gray box, which is this: window.QueryInterface(Components.interfaces.nsIInterfaceRequestor). getInterface(Components.interfaces.nsIDOMWindowUtils). cycleCollect(Components.classes["@mozilla.org/cycle-collector-logger;1"] .createInstance(Components.interfaces.nsICycleCollectorListener)) Then maybe send the file to me somehow. The file will contain URLs you have open, but shouldn't contain any other personally identifiable information.

Hello, I just finished checking, and the problem is still here (with Stylish add-on too) Build identifier: Mozilla/5.0 (Windows NT 5.1; rv:13.0a1) Gecko/20120201 Firefox/13.0a1 SeaMonkey/2.10a1 Times: GC(T+67055.3) Type:Glob, Total:115,2, Wait:0,2, Mark:84,9, Sweep:25,1, FinObj:4,2, FinStr:0,6, FinScr:0,3, FinShp:5,0, DisCod:1,2, DisAnl:1,2, XPCnct:4,6, Destry:0,1, End:9,3, +Chu:0, -Chu:0, Reason:SET_NEW_DOCUMENT CC(T+67056.9) collected: 15329 (15329 waiting for GC), suspected: 4077, duration: 344 ms. ForgetSkippable 2 times before CC, min: 0 ms, max: 16 ms, avg: 8 ms, total: 16 ms, removed: 1738 GC(T+67061.0) Type:Glob, Total:148,7, Wait:0,1, Mark:55,3, Sweep:26,5, FinObj:4,3, FinStr:0,4, FinScr:0,2, FinShp:3,6, DisCod:1,0, DisAnl:1,7, XPCnct:4,9, Destry:0,1, End:71,0, +Chu:0, -Chu:0, Reason:CC_WAITING GC(T+67067.3) Type:Glob, Total:91,3, Wait:0,2, Mark:67,2, Sweep:22,8, FinObj:3,2, FinStr:0,5, FinScr:0,2, FinShp:3,3, DisCod:1,0, DisAnl:1,8, XPCnct:4,9, Destry:0,2, End:5,7, +Chu:0, -Chu:0, Reason:SET_NEW_DOCUMENT GC(T+67085.9) Type:Glob, Total:86,4, Wait:0,2, Mark:56,3, Sweep:28,0, FinObj:5,4, FinStr:1,1, FinScr:0,3, FinShp:3,6, DisCod:2,0, DisAnl:1,9, XPCnct:5,5, Destry:0,1, End:6,9, +Chu:0, -Chu:0, Reason:PAGE_HIDE CC(T+67088.0) collected: 18740 (18740 waiting for GC), suspected: 6201, duration: 343 ms. ForgetSkippable 10 times before CC, min: 0 ms, max: 15 ms, avg: 1 ms, total: 15 ms, removed: 11822 GC(T+67092.1) Type:Glob, Total:80,2, Wait:0,2, Mark:58,4, Sweep:20,7, FinObj:1,9, FinStr:0,1, FinScr:0,2, FinShp:3,3, DisCod:0,8, DisAnl:1,2, XPCnct:5,6, Destry:0,1, End:6,0, +Chu:0, -Chu:0, Reason:CC_WAITING GC(T+67097.1) Type:Glob, Total:96,1, Wait:0,2, Mark:64,3, Sweep:26,8, FinObj:4,1, FinStr:0,2, FinScr:0,2, FinShp:3,6, DisCod:1,2, DisAnl:1,5, XPCnct:6,1, Destry:0,1, End:10,2, +Chu:0, -Chu:0, Reason:PAGE_HIDE CC(T+67099.4) collected: 561 (561 waiting for GC), suspected: 3571, duration: 312 ms. ForgetSkippable 6 times before CC, min: 0 ms, max: 16 ms, avg: 5 ms, total: 32 ms, removed: 1698 GC(T+67103.5) Type:Glob, Total:78,0, Wait:0,2, Mark:56,6, Sweep:20,3, FinObj:1,8, FinStr:0,1, FinScr:0,2, FinShp:3,3, DisCod:0,8, DisAnl:1,2, XPCnct:5,1, Destry:0,1, End:5,5, +Chu:0, -Chu:0, Reason:CC_WAITING about:jank results (11897 samples) 6366 - c-CC::nsCycleCollector_collect 1249 - c-GC::GarbageCollectNow 770 - c-nsEventListenerManager::HandleEventInternal 561 - c-gfx::DrawThebesLayer 526 - c-JS::CallEventHandler 410 - c-JS::EvaluateString 303 - c-Timer::Fire 300 - c-html5::RunFlushLoop 286 - c-Paint::PresShell::Paint 277 - c-layout::DoReflow 248 - c-image::imgFrame::Draw 160 - c-layout::FlushPendingNotifications 131 - c-JS::EvaluateStringWithValue 96 - c-CSS::ProcessRestyles 57 - c-storage::Statement::ExecuteStep 51 - c-PluginModuleParent::NPP_NewStream 37 - c-CC::nsCycleCollector_forgetSkippable 35 - c-event::nsViewManager::DispatchEvent 27 - c-Input::DispatchMouseEvent 2 - c-network::nsHttpChannel::OnStopRequest 2 - c-GC::CycleCollectNow 1 - c-layout::nsLayoutUtils::DrawBackgroundImage 1 - c-content::nsXMLHttpRequest::OnStopRequest 1 - c-network::nsHttpChannel::OnDataAvailable cc heap dump sended on your e-mail

Thanks!

Just FYI, Incremental GC doesn't change anything GC(T+15012.2) TotalTime: 119,6ms, Type: global, MMU(20ms): 0%, MMU(50ms): 0%, MaxPause: 60,4, +chunks: 0, -chunks: 0 Slice 0 @ 26,9ms (Pause: 26,9, Reason: SET_NEW_DOCUMENT): mark: 25,3, mark-roots: 15,1 Slice 5 @ 330,3ms (Pause: 60,4, Reason: REFRESH_FRAME): mark: 23,3, mark-delayed: 0,2, mark-other: 23,0, sweep: 32,6, sweep-obj: 5,7, sweep-string: 0,9, sweep-script: 0,3, sweep-shape: 4,4, discard-code: 0,8, discard-analysis: 2,4, xpconnect: 7,5, deallocate: 0,1 Totals: mark: 80,6, mark-roots: 15,1, mark-delayed: 0,6, mark-other: 23,0, sweep: 32,6, sweep-obj: 5,7, sweep-string: 0,9, sweep-script: 0,3, sweep-shape: 4,4, discard-code: 0,8, discard-analysis: 2,4, xpconnect: 7,5, deallocate: 0,1 CC(T+15017.4) collected: 1515 (1515 waiting for GC), suspected: 2495, duration: 219 ms. ForgetSkippable 11 times before CC, min: 0 ms, max: 47 ms, avg: 7 ms, total: 78 ms, removed: 9286 GC(T+15022.0) TotalTime: 112,7ms, Type: global, MMU(20ms): 0%, MMU(50ms): 5%, MaxPause: 47,2, +chunks: 0, -chunks: 0 Slice 0 @ 25,4ms (Pause: 25,4, Reason: CC_WAITING): mark: 23,9, mark-roots: 13,8 Slice 5 @ 614,6ms (Pause: 47,2, Reason: INTER_SLICE_GC): mark: 18,6, mark-delayed: 0,1, mark-other: 18,5, sweep: 26,7, sweep-obj: 3,5, sweep-string: 0,2, sweep-script: 0,3, sweep-shape: 4,2, discard-code: 0,9, discard-analysis: 1,5, xpconnect: 6,7, deallocate: 0,1 Totals: mark: 82,4, mark-roots: 13,8, mark-delayed: 0,4, mark-other: 18,5, sweep: 26,7, sweep-obj: 3,5, sweep-string: 0,2, sweep-script: 0,3, sweep-shape: 4,2, discard-code: 0,9, discard-analysis: 1,5, xpconnect: 6,7, deallocate: 0,1 CC(T+15062.2) collected: 1240 (1240 waiting for GC), suspected: 565, duration: 156 ms. ForgetSkippable 12 times before CC, min: 0 ms, max: 31 ms, avg: 2 ms, total: 31 ms, removed: 2410

(In reply to Phoenix from comment #23) Are you sure Incremental GC is enabled for you? Have a look at about:support, you can search for "Incremental GC" there. Beware that Incremental GC gets deactivated dynamically, see f.e. Bug 728686 and the bugs that one blocks.

There's slice information, so I think incremental GC is enabled. Incremental GC won't help with CC, though.

Also, incremental GC is helping a little here. It's halving the GC times (the MaxPause number is the relevant one in terms of responsiveness).

(In reply to Stefan Fleiter (:sfleiter) from comment #24) > (In reply to Phoenix from comment #23) > > Are you sure Incremental GC is enabled for you? Yes, I rechecked this couple of times and aware about those autodeactivations :) (In reply to Andrew McCreight [:mccr8] from comment #25) > Incremental GC won't help with CC, though. Ok

Current status update: seems that landing Bug 695480 improved situation here, with May builds I no longer able to achieve growing cc times, after repeating test steps most cc times back to normal, but there are single spikes with 100+ ms, which are absent if NoScript is not installed. It looks like root issue still present, but now it isolated in one compartment and doesn't spread.

I can't reproduce this with current NoScript builds with Firefox 13 or 14. After opening and closing a dozen or so windows with the linked URL, and scripts enabled for its domain, CC times jump briefly but settle down pretty quickly. It does seem to be notably better on 14, though. Less of a spike, and where with 13 they settled to 70-80ms, on 14 they settled to 10-20ms.