I am testing the current Aurora version. I was closing my MBP over night and opened it again without touching the browser. Now I see CCs every 5 seconds without any GCs in between and they don't stop. CC(T+33620.4) collected: 0 (112 waiting for GC), suspected: 567, duration: 12 ms. ForgetSkippable 5 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 0 ms, removed: 140 CC(T+33625.5) collected: 0 (112 waiting for GC), suspected: 598, duration: 12 ms. ForgetSkippable 4 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 0 ms, removed: 142

I need to land Bug 723157 to Aurora. That might help a bit. But CC runs if there are new suspected objects. Something is causing those.

I guess I found the tab that's causing it. Just open techcrunch.com and you see a CC every 5 sec.

I see the same behavior on Nightly with TC.

With Firefox 11, I'm getting CCs every 15 seconds on Tech Crunch, with a suspected count of a little under 1500. They are about 15-38ms long. The GC is running about once a minute. It sounds like TC is suspecting about 100 nodes a second (that are mostly unoptimizable), and the threshold in 12 is just a third what it is in 11, so we run the CC three times as long. One slightly unsettling thing is that in 11 it is freeing about 50 or so things each time. Are we missing those things in 12+ or are they just freed through some other means?

On Nightly, I'm getting CCs every 5 seconds as Gregor reported. The CCs are only 3-7ms, so I'd argue that the experience (at least with just TC open) is actually better, even though we're running it 3 times as often. That's both in terms of latency and throughput. Of course, if you have many tabs open, and you end up having to trace through a lot of stuff the CC can't optimize away, then it is going to be worse. It seems to be running the GC less. I'm seeing 100 seconds between GCs instead of 60. That could be bad. But probably just related to how the CC isn't finding anything. So, I think it is worth investigating what the CC is freeing in 11, and whether that's just leaking in 12, or being cleaned up through normal refcounting.

I tested TC with Smaug's latest round of patches that landed today. It still runs every 5 seconds, but it is always collecting some things. Not many, 23, but at least we don't have that disturbing change from earlier versions. There's a bunch of small things, but the largest structure in the graph is this thing. It has a very regular structure. The pink nodes are XPCWrappedNatives. Shaded nodes are roots in the CC graph. Nodes that look like "M:5" mean that there were 5 JS nodes in a strongly connected component that have been merged together. Shading doesn't work for merged nodes, so some of those clumps could be marked or something. But aside from the that, it looks like the nsXPCWrappedJS (nsIFeedEntry) is keeping alive a bunch of stuff.

Bug 726331 fixes this, at least on Nightly with no other tabs open. There's just a ton of silly stuff being added to the purple buffer, causing CCs to be triggered frequently.

Thanks for the report, Gregor, this was an interesting set of bugs to look into that should help a lot with how often the CC is run.

For me on Nightly, the CC didn't run for over 2 minutes, sitting on Tech Crunch with nothing else open. When I interacted with the browser again, it triggered. CC(T+28.0) collected: 373 (373 waiting for GC), suspected: 1356, duration: 4 ms. ForgetSkippable 14 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 8 ms, removed: 9230 GC(T+28.5) Type:Glob, Total:44.2, Wait:1.9, Mark:20.7, Sweep:19.9, FinObj:2.9, FinStr:0.5, FinScr:0.4, FinShp:1.9, DisCod:1.7, DisAnl:10.0, XPCnct:0.9, Destry:0.0, End:2.6, +Chu:7, -Chu:1, Reason:SET_NEW_DOCUMENT GC(T+88.5) Type:Glob, Total:35.4, Wait:0.2, Mark:22.7, Sweep:10.1, FinObj:1.9, FinStr:0.6, FinScr:0.2, FinShp:1.1, DisCod:0.6, DisAnl:3.7, XPCnct:0.8, Destry:0.0, End:3.2, +Chu:2, -Chu:0, Reason:MAYBEGC CC(T+158.4) collected: 408 (408 waiting for GC), suspected: 504, duration: 10 ms. ForgetSkippable 115 times before CC, min: 0 ms, max: 3 ms, avg: 0 ms, total: 47 ms, removed: 14643 GC(T+162.4) Type:Glob, Total:33.4, Wait:0.2, Mark:21.6, Sweep:8.4, FinObj:1.9, FinStr:0.8, FinScr:0.2, FinShp:1.0, DisCod:0.6, DisAnl:1.9, XPCnct:0.7, Destry:0.0, End:4.0, +Chu:0, -Chu:1, Reason:CC_WAITING GC(T+242.5) Type:Glob, Total:31.4, Wait:0.2, Mark:21.7, Sweep:8.1, FinObj:1.7, FinStr:0.7, FinScr:0.2, FinShp:1.0, DisCod:0.6, DisAnl:1.8, XPCnct:0.8, Destry:0.0, End:2.1, +Chu:2, -Chu:0, Reason:MAYBEGC

Gregor is seeing this again, except it is every 15 seconds instead of every 5. Presumably there's some other crud that is getting churned up now by TechCrunch's cruel machinations.

I'm seeing this again, with two TechCrunch windows open. CC every 6 seconds. I need to confirm that happens in a clean build, but it seems to be the case.

These are the most common things in the purple buffer, out of a total of 228. Maybe this could be helped by bug 831360. 51 nsDOMMediaQueryList 21 nsXBLBinding 16 nsDOMEvent 16 FragmentOrElement (XUL) thumb http://techcrunch.com/wp-content/themes/vip/tctechcrunch2/_uac/adpage.html 16 FragmentOrElement (XUL) slider http://techcrunch.com/wp-content/themes/vip/tctechcrunch2/_uac/adpage.html 13 nsPresContext 9 nsXULTemplateBuilder 9 nsJSScriptTimeoutHandler 9 nsEventListenerManager 6 nsJSContext 5 nsJSArgArray

Purple nodes are from the purple buffer, red nodes are XPConnect roots. Note that anything that is both will only be shown as an XPConnect root.

This still is not super awesome. 17:03:02.396 CC(T+23363.3) duration: 9ms, suspected: 545, visited: 1436 RCed and 816 GCed, collected: 120 RCed and 98 GCed (218|71 waiting for GC) ForgetSkippable 11 times before CC, min: 0 ms, max: 16 ms, avg: 3 ms, total: 35 ms, sync: 0 ms, removed: 3171 17:03:08.743 CC(T+23369.7) duration: 8ms, suspected: 388, visited: 1174 RCed and 681 GCed, collected: 0 RCed and 0 GCed (218|177 waiting for GC) ForgetSkippable 11 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 10 ms, sync: 0 ms, removed: 2037 17:03:15.101 CC(T+23376.1) duration: 23ms, suspected: 361, visited: 1044 RCed and 681 GCed, collected: 0 RCed and 0 GCed (218|291 waiting for GC) ForgetSkippable 13 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 12 ms, sync: 0 ms, removed: 2106 17:03:27.091 CC(T+23388.0) duration: 8ms, suspected: 435, visited: 1191 RCed and 662 GCed, collected: 2 RCed and 0 GCed (220|621 waiting for GC) ForgetSkippable 26 times before CC, min: 0 ms, max: 1 ms, avg: 1 ms, total: 26 ms, sync: 0 ms, removed: 5231 17:03:39.197 CC(T+23400.2) duration: 11ms, suspected: 1403, visited: 1456 RCed and 661 GCed, collected: 48 RCed and 0 GCed (268|996 waiting for GC) ForgetSkippable 27 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 25 ms, sync: 0 ms, removed: 5182

Hmm, we should do more BBP and/or CanSkip to be able deal with the situation during forgetSkippable.

Yeah, the details of my analysis last time I looked at it are in bug 831360. Basically it was all nsDOMMediaQueryList. You convinced me that optimizing out nsPresContext was too scary, so I stopped working on it.

Well, hopefully this is okay now...