For the last couple of days I've been experiencing very frequent (every 15-30 seconds, it seems) tiny hangs in Nightly; they're perhaps 100-250 ms long: enough to interrupt scrolling or typing, but not enough that the app actually hangs. I've tried profiling with Instruments, and it seems that the largest portion of the time Firefox is sitting idle with several tabs open is spent under places like js::gc::FinalizeArenas, nsCycleCollector::FinishCollection, etc. How can I find out what's actually going on? If garbage is being generated, how can I find out what's generating it?

For a start, flip javascript.options.mem.log to true in preferences and then watch your error console to see how often we're collecting and how long the collections take? Is this a build with useful symbols?

Yep - shark build. Seems like it is GC: CC timestamp: 1318477371148857, collected: 16880 (16893 waiting for GC), suspected: 18005, duration: 82 ms. GC mode: full, timestamp: 1318477375334039, duration: 184 ms. CC timestamp: 1318477380526196, collected: 148 (148 waiting for GC), suspected: 1420, duration: 64 ms.

Hmm. I have 150ms GC pauses, and I don't notice anything, so 180 doesn't seem too crazy. It is a little high, I guess.

Anything more than 20ms hurts animations.

If you have symbols, want to breakpoint in js_GC and see what's calling it? As far as where garbage is being generated, you could breakpoint in js::NewGCThing, then when hit examine the JS stack. Sadly, this is an opt build, so no DumpJSStack. :(

Sure, but it sounds like these pauses are bad enough that he is noticing them during normal browsing. So either they are longer pauses or more frequent than usual. about:memory will show you what is taking up space. You can copy and paste that here and we can see if anything unusual pops out at us.

(In reply to Boris Zbarsky (:bz) from comment #5) > As far as where garbage is being generated, you could breakpoint in > js::NewGCThing, then when hit examine the JS stack. Sadly, this is an opt > build, so no DumpJSStack. :( Yeah, I need to figure out if there's any reason for that. You can do CC dumps in an opt build, so it is a shame you can't do GC dumps too.

Actually, looks like DumpJSStack works in opt builds now. So you can use that; just make sure to disable the NewGCThing breakpoint before calling DumpJSStack, since I'm pretty sure that call can allocate gc things.

I opened my debug build and can still reproduce this issue (only collects are now ~500ms).

I collected some data (with gdb on a debug build) for the domains that cycle collected objects are from. I ran through at least 2 full cycle collections. Here are my findings: 1 https://aus3.mozilla.org/update/3/Firefox/10.0a1/20111012171528/Darwin_x86_64-gcc3/en-US/default/Darwin%2010.8.0/default/default/update.xml 8353 https://tbpl.mozilla.org/?usebuildbot=1 1 https://tbpl.mozilla.org/?usebuildbot=1&tree=Mozilla-Inbound 2 https://www.rememberthemilk.com/channel/?zx=1318534887122&rid=3 2 https://www.rememberthemilk.com/channel/?zx=1318534917350&rid=4 2 https://www.rememberthemilk.com/channel/?zx=1318534948785&rid=5 2 https://www.rememberthemilk.com/channel/?zx=1318534978993&rid=6 11 https://www.yammer.com/mozilla.com/#/Threads/index?type=algo

I uploaded a CC heap log at http://people.mozilla.org/~jdrew/cc-edges-1.86686.log.bz2 - too big to attach to bugzilla, even bzip2'd.

I ran my garbage analysis script on the log, but nothing really jumps out at me. One thing that seems a little odd is this: 1 nsDocument ([none]) https://www.rememberthemilk.com/channel/?zx=1318543744870&rid=2 Did you close the tab for this right before you ran the dump command? Things that had more than 5 instances in the garbage: 10 nsTypedSelection 8 JS Object (Function) (global=124d3c060) 8 JS Object (Object) (global=124d3c060) 6 nsEventListenerManager

Here's the complete list of the types of objects that are being collected.

(In reply to Andrew McCreight [:mccr8] from comment #13) > One thing that seems a little odd is this: > > 1 nsDocument ([none]) > https://www.rememberthemilk.com/channel/?zx=1318543744870&rid=2 > > Did you close the tab for this right before you ran the dump command? No. I have a Remember the Milk app tab.

The nsDocument could well be an XHR response document or something. Comment 11 is presumably nsGenericElements, not all CCable objects. But it's a decent proxy for what's going on.

Seems likely that this is the same as bug 702813?

Either way this was definitely a snappy issue. I've "fixed" it by not having TBPL (and, indeed, anything else) as app tabs.

No bug 702813, that will cause long CCs, but not affect GCs. It could be related to bug 711900

Checking the dates from the first post, it looks like this could be a dupe of bug 711900. The suspected cause of that is a bug that landed on Oct 7, while comment 0 reports that on Oct 12 he has been experiencing hangs for the "last couple of days".

In reply to Andrew McCreight [:mccr8] from comment #20) > Checking the dates from the first post, it looks like this could be a dupe > of bug 711900. The suspected cause of that is a bug that landed on Oct 7, > while comment 0 reports that on Oct 12 he has been experiencing hangs for > the "last couple of days". Why not dupe this?

Ah, I knew I'd seen Joe having some pause problems, but couldn't remember where. Joe, have you seen these problems in Nightly since around the first of January? A patch landed around the end of December that fixed the problem I think you were having. Could you try going back to your old habits of having TBPL open and see if it is any better? Thanks! Assigning to myself so I will remember to follow up and dupe this.

Will do. I've definitely had occasions of 2+ second pauses over the last week or two, though; that was with several reddit tabs open. Will keep you up to date.

Joe, is nightly any better? We've landed a bunch of improvements recently.

Joe? (In reply to Andrew McCreight [:mccr8] from comment #24) > Joe, is nightly any better? We've landed a bunch of improvements recently.

I haven't been running with the same set of tabs as in comment 0 for quite some time, and when I have a heavy load of tabs, I haven't had pauses IIRC. I'll reopen this bug if I run into this again.