The default bug view has changed. See this FAQ.

incremental GCs are very rare

RESOLVED FIXED in mozilla16

Status

()

Core
JavaScript Engine
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: Ehsan, Assigned: billm)

Tracking

Trunk
mozilla16
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox15- wontfix)

Details

Attachments

(1 attachment)

(Reporter)

Description

5 years ago
I've been watching my GC times after IGC was turned on again, and it seems like I never get IGC working for me, all I get are entries like these:

GC(T+14450.0) Total Time: 187.9ms, Compartments Collected: 599, Total Compartments: 599, MMU (20ms): 0%, MMU (50ms): 0%, Reason: CC_WAITING, Nonincremental Reason: requested, Allocated: 198MB, +Chunks: 0, -Chunks: 0
    Totals: Mark: 141.7ms, Mark Roots: 5.3ms, Mark Other: 14.9ms, Finalize Start Callback: 0.7ms, Sweep: 45.3ms, Sweep Compartments: 25.4ms, Sweep Object: 2.3ms, Sweep String: 0.2ms, Sweep Script: 1.0ms, Sweep Shape: 6.4ms, Discard Code: 2.3ms, Discard Analysis: 13.5ms, Discard TI: 2.0ms, Sweep Types: 6.3ms, Clear Script Analysis: 1.2ms, Finalize End Callback: 2.6ms, End Callback: 0.6ms

GC(T+14485.5) Total Time: 207.0ms, Compartments Collected: 611, Total Compartments: 611, MMU (20ms): 0%, MMU (50ms): 0%, Reason: PAGE_HIDE, Nonincremental Reason: requested, Allocated: 208MB, +Chunks: 0, -Chunks: 0
    Totals: Purge: 2.5ms, Mark: 145.9ms, Mark Roots: 8.9ms, Mark Other: 16.5ms, Finalize Start Callback: 0.7ms, Sweep: 54.8ms, Sweep Compartments: 29.7ms, Sweep Object: 5.7ms, Sweep String: 0.9ms, Sweep Script: 1.0ms, Sweep Shape: 7.0ms, Discard Code: 2.9ms, Discard Analysis: 15.1ms, Discard TI: 1.1ms, Sweep Types: 6.3ms, Clear Script Analysis: 1.2ms, Finalize End Callback: 3.0ms, End Callback: 3.4ms

GC(T+14450.0) Total Time: 187.9ms, Compartments Collected: 599, Total Compartments: 599, MMU (20ms): 0%, MMU (50ms): 0%, Reason: CC_WAITING, Nonincremental Reason: requested, Allocated: 198MB, +Chunks: 0, -Chunks: 0
    Totals: Mark: 141.7ms, Mark Roots: 5.3ms, Mark Other: 14.9ms, Finalize Start Callback: 0.7ms, Sweep: 45.3ms, Sweep Compartments: 25.4ms, Sweep Object: 2.3ms, Sweep String: 0.2ms, Sweep Script: 1.0ms, Sweep Shape: 6.4ms, Discard Code: 2.3ms, Discard Analysis: 13.5ms, Discard TI: 2.0ms, Sweep Types: 6.3ms, Clear Script Analysis: 1.2ms, Finalize End Callback: 2.6ms, End Callback: 0.6ms

I don't know if this is expected or not, but I have not seen even a single GC so far that does not have a "Nonincremental Reason" (not that I watch every GC I get, but I do watch the error console pretty heavily).
If you have about:telemetry installed, you can check GC_NON_INCREMENTAL.  FYI, I'm also seeing the same thing: 122 out of 122 of my GC have been non-incremental, despite GC_INCREMENTAL_DISABLED being 0 everywhere.
Blocks: 735099
Summary: Incremental GC is not working for me → Incremental GC not actually being triggered
Version: unspecified → Trunk
I have seen it do a couple of slices a few times.  I'm not sure what that means precisely:

GC(T+2243.9) Total Time: 224.7ms, Compartments Collected: 393, Total Compartments: 393, MMU (20ms): 0%, MMU (50ms): 0%, Max Pause: 201.5ms, Nonincremental Reason: requested, Allocated: 96MB, +Chunks: 3, -Chunks: 0
    Slice: 0, Pause: 23.2 (When: 23.2ms, Reason: MAYBEGC): Purge: 0.1ms, Mark: 16.8ms, Mark Roots: 6.7ms, Discard Code: 4.6ms
    Slice: 1, Pause: 201.5 (When: 324.9ms, Reason: INTER_SLICE_GC, Reset: requested): Mark: 107.1ms, Mark Roots: 5.3ms, Mark Other: 4.3ms, Finalize Start Callback: 0.5ms, Sweep: 78.4ms, Sweep Compartments: 54.0ms, Sweep Object: 5.2ms, Sweep String: 1.4ms, Sweep Script: 0.7ms, Sweep Shape: 5.8ms, Discard Code: 2.3ms, Discard Analysis: 42.2ms, Discard TI: 4.4ms, Sweep Types: 5.4ms, Clear Script Analysis: 1.4ms, Finalize End Callback: 2.7ms, Deallocate: 0.1ms, End Callback: 9.8ms
    Totals: Purge: 0.2ms, Mark: 123.8ms, Mark Roots: 12.0ms, Mark Other: 4.3ms, Finalize Start Callback: 0.5ms, Sweep: 78.4ms, Sweep Compartments: 54.0ms, Sweep Object: 5.2ms, Sweep String: 1.4ms, Sweep Script: 0.7ms, Sweep Shape: 5.8ms, Discard Code: 6.9ms, Discard Analysis: 42.2ms, Discard TI: 4.4ms, Sweep Types: 5.4ms, Clear Script Analysis: 1.4ms, Finalize End Callback: 2.7ms, Deallocate: 0.1ms, End Callback: 9.8ms

Comment 3

5 years ago
about:telemetry isn't required, just that javascript.options.mem.log is set to true :)

Comment 4

5 years ago
oh, my bad, you were speaking of that specific GC function.
(Reporter)

Comment 5

5 years ago
(In reply to Andrew McCreight [:mccr8] from comment #1)
> If you have about:telemetry installed, you can check GC_NON_INCREMENTAL. 
> FYI, I'm also seeing the same thing: 122 out of 122 of my GC have been
> non-incremental, despite GC_INCREMENTAL_DISABLED being 0 everywhere.

GC_NON_INCREMENTAL
490 samples, average = 1, sum = 488

Now, how you would make sense of what this means is beyond me.  But the chart shows 2 samples of 0, and 488 of 1, which tells me that we do IGC 2/490 % of the time for me.  ;-)

Comment 6

5 years ago
I launched Nightly in a temp profile and installed memchaser, and let it sit for 10-15 seconds to find it stayed at GC constantly with 23-35ms cycles


Normally letting it sit for roughly 10-15 seconds the addonbar info would start reflecting concurrent Incremental collection and sit at roughly 10-13ms.

similarly, my active profile sits at 50-60ms GC's from a fresh start where as with the build i was using prior would be 17ms iGC's.

Comment 7

5 years ago
I started testing backwards to find when this started happening and thought i had narrowed it down to the 3rd, but subsequent retesting of the build from the 2nd and 1st also failed to perform any Incremental slices.

Updated

5 years ago
tracking-firefox15: --- → ?

Comment 8

5 years ago
MC
Working
20120525113255
http://hg.mozilla.org/mozilla-central/rev/034bbdc7b9c9

Broken
20120527030515
http://hg.mozilla.org/mozilla-central/rev/133aa3a2ef0a

Comment 9

5 years ago
nvm that last post, i screwed up by forgetting to set incremental back to on in the 27th build.
(In reply to Ehsan Akhgari [:ehsan] from comment #5)
> Now, how you would make sense of what this means is beyond me.  But the
> chart shows 2 samples of 0, and 488 of 1, which tells me that we do IGC
> 2/490 % of the time for me.  ;-)
Yeah, it would be nice if it showed a % for booleans or something.  Thanks for looking that up.  That is interesting that you are getting a few incremental GCs.

Comment 11

5 years ago
Not all that strange, i also got one or 2 completely random incremental slices and then was not able to get them again
(Reporter)

Comment 12

5 years ago
(In reply to Andrew McCreight [:mccr8] from comment #10)
> (In reply to Ehsan Akhgari [:ehsan] from comment #5)
> > Now, how you would make sense of what this means is beyond me.  But the
> > chart shows 2 samples of 0, and 488 of 1, which tells me that we do IGC
> > 2/490 % of the time for me.  ;-)
> Yeah, it would be nice if it showed a % for booleans or something.  Thanks
> for looking that up.  That is interesting that you are getting a few
> incremental GCs.

Vlad and Jeff sit near me at the office, and they're getting roughly the same.

Comment 13

5 years ago
This time i did it right

MC
Working
20120601030520
http://hg.mozilla.org/mozilla-central/rev/73783bf75c4c

Not/Barely Working
20120602030527
http://hg.mozilla.org/mozilla-central/rev/5199196b65ec

Comment 14

5 years ago
i found the cause of the random Incremental Slice;  Having the window minimised to tray.

Comment 15

5 years ago
Taskbar*
(Reporter)

Comment 16

5 years ago
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=73783bf75c4c&tochange=5199196b65ec

Time for somebody to bisect this I guess!  :-)

Comment 17

5 years ago
im betting something within http://hg.mozilla.org/mozilla-central/pushloghtml?changeset=12ab69851e05
That includes the push that re-enabled incremental GC, which also flipped the javascript.options.mem.disable_explicit_compartment_gc pref to true.  It could be the case that incremental scheduling somehow has come to depend on that, which also affected how GCs are scheduled.  Try flipping that to false and see what happens.  As a note, if you try to bisect earlier to see how that goes, the pref used to be javascript.options.disable_explicit_compartment_gc.

http://hg.mozilla.org/mozilla-central/rev/a6be10cfee3f
I flipped javascript.options.mem.disable_explicit_compartment_gc to false, and now my GCs are all incremental.
(Reporter)

Comment 20

5 years ago
(In reply to Andrew McCreight [:mccr8] from comment #19)
> I flipped javascript.options.mem.disable_explicit_compartment_gc to false,
> and now my GCs are all incremental.

I tried it as well, and I see a lot of incremental GCs now, with an occasional non-incremental one.

Comment 21

5 years ago
good call Andrew,

Is this to be expected Bill?
I think bug 758034 is supposed to fix this, or something like it.
Depends on: 758034

Comment 23

5 years ago
I've also seen this issue on:
Mozilla/5.0 (Windows NT 6.1; rv:15.0) Gecko/20120606 Firefox/15.0a2 (20120606042008)
OS: Mac OS X → All
Hardware: x86 → All

Comment 24

5 years ago
Mozilla/5.0 (X11; Linux i686; rv:15.0) Gecko/20120608 Firefox/15.0a2
Mozilla/5.0 (Windows NT 6.1; rv:15.0) Gecko/20120606 Firefox/15.0a2 (20120606042008)

Apparently, IGC gets triggered but quite rarely. When using Aurora for about 2 hours I barely saw 2-3 GCs without a "Nonincremental reason" in the Error console.
Good point.
Summary: Incremental GC not actually being triggered → incremental GCs are very rare

Comment 26

5 years ago
(In reply to Ioana Budnar [QA] from comment #24)
> Mozilla/5.0 (X11; Linux i686; rv:15.0) Gecko/20120608 Firefox/15.0a2
> Mozilla/5.0 (Windows NT 6.1; rv:15.0) Gecko/20120606 Firefox/15.0a2
> (20120606042008)
> 
> Apparently, IGC gets triggered but quite rarely. When using Aurora for about
> 2 hours I barely saw 2-3 GCs without a "Nonincremental reason" in the Error
> console.

Also checked on Mac 10.7.4 with the same build. The behaviour is the same.
(Assignee)

Comment 27

5 years ago
Created attachment 631782 [details] [diff] [review]
fix

This was a big screwup on my part. This patch will be superseded by the ones in bug 758034, but this one is simpler and hopefully we can get it into Aurora.
Assignee: general → wmccloskey
Status: NEW → ASSIGNED
Attachment #631782 - Flags: review?(bugs)
Attachment #631782 - Flags: review?(bugs) → review+
(Assignee)

Comment 28

5 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/828da55601e7
Target Milestone: --- → mozilla16
https://hg.mozilla.org/mozilla-central/rev/828da55601e7
Status: ASSIGNED → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
Comment on attachment 631782 [details] [diff] [review]
fix

[Approval Request Comment]
Bug caused by (feature/regressing bug #): NA
User impact if declined: Longer GC pauses
Testing completed (on m-c, etc.): Just landed to m-c
Risk to taking this patch (and alternatives if risky): 
  Somewhat risky, since incremental GC hasn't got lots of testing
  (Alternative is to disable incremental GC on Aurora and re-enable
   explicit compartment GCs)
String or UUID changes made by this patch: NA
Attachment #631782 - Flags: approval-mozilla-aurora?
(In reply to Olli Pettay [:smaug] from comment #30)
> Risk to taking this patch (and alternatives if risky): 
>   Somewhat risky, since incremental GC hasn't got lots of testing
>   (Alternative is to disable incremental GC on Aurora and re-enable
>    explicit compartment GCs)

How would a regression from this patch look? Memory/performance issues?
(In reply to Alex Keybl [:akeybl] from comment #31)
> How would a regression from this patch look? Memory/performance issues?
It isn't a regression per se.  IGC is disabled in 14.  It is "enabled" in 15, but due to this bug is basically behaving like it is disabled.  I think there may be additional patches that are needed aside from this one to make IGC okay for 15.  billm would know more.
See comment 27.
I believe the patch here should be enough for FF15.
iGC has behaved quite ok on m-c after the patch landed.
Comment on attachment 631782 [details] [diff] [review]
fix

Approving for Aurora so we can get some bake time to confirm this is enough for 15.
Attachment #631782 - Flags: approval-mozilla-aurora? → approval-mozilla-aurora+
Setting tracking in case we need to disable this patch in favour of the ones in bug 758034 or some other backout/followup is needed.
status-firefox15: --- → affected
tracking-firefox15: ? → +
https://tbpl.mozilla.org/?tree=Try&rev=c929ad74c0f4
Not looking good. Bill, is Aurora missing some other GC patches?

Comment 38

5 years ago
does javascript.options.mem.disable_explicit_compartment_gc;false improve things on aurora?
(Assignee)

Comment 39

5 years ago
For Aurora, Bobby needs to land the new expando stuff in bug 758415. That already has Aurora approval, but I think it depends on bug 763381, which just landed.
(Assignee)

Comment 40

5 years ago
We're not going to land this on Aurora. Instead, we're going to do bug 768688.
[Triage Comment]
Removing tracking-firefox15 as per comment 40 - bug 768788 has been tracked and landed in 15.
status-firefox15: affected → wontfix
tracking-firefox15: + → -
You need to log in before you can comment on or make changes to this bug.