725377 - Very frequent cycle collections on TechCrunch

Status: RESOLVED INCOMPLETE

(Core :: DOM: Core & HTML, defect)

Description

[Gregor Wagner [:gwagner]]

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

Comment 1

[Olli Pettay [:smaug][[e-mail]]]

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.

Comment 2

[Gregor Wagner [:gwagner]]

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

Comment 3

[Andrew McCreight [:mccr8]]

I see the same behavior on Nightly with TC.

Comment 4

[Andrew McCreight [:mccr8]]

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?

Comment 5

[Andrew McCreight [:mccr8]]

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.

Comment 6

[Andrew McCreight [:mccr8]]

Attachment: MEGASTRUCTURE!

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.

Comment 7

[Andrew McCreight [:mccr8]]

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.

Comment 8

[Andrew McCreight [:mccr8]]

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.

Comment 9

[Andrew McCreight [:mccr8]]

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

Comment 10

[Andrew McCreight [:mccr8]]

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.

Comment 11

[Andrew McCreight [:mccr8]]

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.

Comment 12

[Andrew McCreight [:mccr8]]

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

Comment 13

[Andrew McCreight [:mccr8]]

Attachment: non-garbage parts of the graph

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.

Comment 14

[Andrew McCreight [:mccr8]]

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

Comment 15

[Olli Pettay [:smaug][[e-mail]]]

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

Comment 16

[Andrew McCreight [:mccr8]]

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.

Comment 17

[Andrew McCreight [:mccr8]]

Well, hopefully this is okay now...