Closed Bug 761739 Opened 12 years ago Closed 12 years ago

incremental GCs are very rare

Categories

(Core :: JavaScript Engine, defect)

Product:
Core
Component:
JavaScript Engine
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla16
Tracking Flags:
Tracking Status
firefox15 - wontfix

People

(Reporter: ehsan.akhgari, Assigned: billm)

References

Details

Attachments

(1 file)

fix
834 bytes, patch
smaug
: review+
lsblakk
: approval-mozilla-aurora+
Details | Diff | Splinter Review 
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
about:telemetry isn't required, just that javascript.options.mem.log is set to true :)
oh, my bad, you were speaking of that specific GC function.
(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.  ;-)
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.
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.
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.
Not all that strange, i also got one or 2 completely random incremental slices and then was not able to get them again
(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.
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
i found the cause of the random Incremental Slice;  Having the window minimised to tray.
Taskbar*
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.
(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.
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
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
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
(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.
Attached patch fix — — Splinter Review 
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+
https://hg.mozilla.org/mozilla-central/rev/828da55601e7
Status: ASSIGNED → RESOLVED
Closed: 12 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: ? → +
Not looking good. Bill, is Aurora missing some other GC patches?
does javascript.options.mem.disable_explicit_compartment_gc;false improve things on aurora?
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.
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.

Attachment

General

Creator:
Created:
Updated:
Size: