Very frequent small hangs, seemingly in GC/cycle collector

RESOLVED INCOMPLETE

Status

()

RESOLVED INCOMPLETE
7 years ago
7 years ago

People

(Reporter: joe, Assigned: mccr8)

Tracking

Trunk
x86
Mac OS X
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [Snappy:P2])

Attachments

(3 attachments)

(Reporter)

Description

7 years ago
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?
(Reporter)

Comment 2

7 years ago
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.
(Assignee)

Comment 3

7 years ago
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

7 years ago
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.  :(
(Assignee)

Comment 6

7 years ago
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.
(Assignee)

Comment 7

7 years ago
(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.
(Reporter)

Comment 9

7 years ago
Created attachment 566892 [details]
my about:memory after being open ~12 hours
(Reporter)

Comment 10

7 years ago
Created attachment 566906 [details]
more verbose about:memory, opened in debug mode

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

Comment 12

7 years ago
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.
(Assignee)

Comment 13

7 years ago
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
(Assignee)

Comment 14

7 years ago
Created attachment 566963 [details]
census of garbage objects from CC log

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

Comment 15

7 years ago
(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.
(Reporter)

Comment 17

7 years ago
Seems likely that this is the same as bug 702813?
(Reporter)

Comment 18

7 years ago
Either way this was definitely a snappy issue. I've "fixed" it by not having TBPL (and, indeed, anything else) as app tabs.
Whiteboard: [Snappy]
(Assignee)

Comment 19

7 years ago
No bug 702813, that will cause long CCs, but not affect GCs.  It could be related to bug 711900
(Assignee)

Comment 20

7 years ago
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".
Depends on: 711900

Comment 21

7 years ago
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?
(Assignee)

Comment 22

7 years ago
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.
Assignee: general → continuation
(Reporter)

Comment 23

7 years ago
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.
(Assignee)

Comment 24

7 years ago
Joe, is nightly any better?  We've landed a bunch of improvements recently.
Whiteboard: [Snappy] → [Snappy:P2]

Comment 25

7 years ago
Joe?

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

Comment 26

7 years ago
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.
Status: NEW → RESOLVED
Last Resolved: 7 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.