694243 - Very frequent small hangs, seemingly in GC/cycle collector

Status: RESOLVED INCOMPLETE

(Core :: JavaScript Engine, defect)

Description

[Joe Drew (not getting mail)]

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?

Comment 1

[Boris Zbarsky [:bzbarsky]]

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?

Comment 2

[Joe Drew (not getting mail)]

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.

Comment 3

[Andrew McCreight [:mccr8]]

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.

Comment 4

[Andreas Gal :gal]

Anything more than 20ms hurts animations.

Comment 5

[Boris Zbarsky [:bzbarsky]]

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.  :(

Comment 6

[Andrew McCreight [:mccr8]]

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.

Comment 7

[Andrew McCreight [:mccr8]]

(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.

Comment 8

[Boris Zbarsky [:bzbarsky]]

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.

Comment 9

[Joe Drew (not getting mail)]

Attachment: my about:memory after being open ~12 hours

Comment 10

[Joe Drew (not getting mail)]

Attachment: more verbose about:memory, opened in debug mode

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

Comment 11

[Joe Drew (not getting mail)]

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

Comment 12

[Joe Drew (not getting mail)]

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.

Comment 13

[Andrew McCreight [:mccr8]]

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

Comment 14

[Andrew McCreight [:mccr8]]

Attachment: census of garbage objects from CC log

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

Comment 15

[Joe Drew (not getting mail)]

(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.

Comment 16

[Boris Zbarsky [:bzbarsky]]

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.

Comment 17

[Joe Drew (not getting mail)]

Seems likely that this is the same as bug 702813?

Comment 18

[Joe Drew (not getting mail)]

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

Comment 19

[Andrew McCreight [:mccr8]]

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

Comment 20

[Andrew McCreight [:mccr8]]

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".

Comment 21

[(dormant account)]

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?

Comment 22

[Andrew McCreight [:mccr8]]

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.

Comment 23

[Joe Drew (not getting mail)]

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.

Comment 24

[Andrew McCreight [:mccr8]]

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

Comment 25

[Wayne Mery (:wsmwk)]

Joe?

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

Comment 26

[Joe Drew (not getting mail)]

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.