Last Comment Bug 761739 - incremental GCs are very rare
: incremental GCs are very rare
Status: RESOLVED FIXED
:
Product: Core
Classification: Components
Component: JavaScript Engine (show other bugs)
: Trunk
: All All
: -- normal with 1 vote (vote)
: mozilla16
Assigned To: Bill McCloskey (:billm)
:
:
Mentors:
Depends on: 758034
Blocks: IncrementalGC 735099
  Show dependency treegraph
 
Reported: 2012-06-05 12:00 PDT by :Ehsan Akhgari
Modified: 2012-07-18 09:16 PDT (History)
21 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
-
wontfix


Attachments
fix (834 bytes, patch)
2012-06-10 16:20 PDT, Bill McCloskey (:billm)
bugs: review+
lukasblakk+bugs: approval‑mozilla‑aurora+
Details | Diff | Splinter Review

Description :Ehsan Akhgari 2012-06-05 12:00:39 PDT
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).
Comment 1 Andrew McCreight [:mccr8] 2012-06-05 12:03:43 PDT
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.
Comment 2 Andrew McCreight [:mccr8] 2012-06-05 12:04:50 PDT
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 Danial Horton 2012-06-05 12:11:46 PDT
about:telemetry isn't required, just that javascript.options.mem.log is set to true :)
Comment 4 Danial Horton 2012-06-05 12:12:39 PDT
oh, my bad, you were speaking of that specific GC function.
Comment 5 :Ehsan Akhgari 2012-06-05 12:12:44 PDT
(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 Danial Horton 2012-06-05 12:16:04 PDT
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 Danial Horton 2012-06-05 12:18:10 PDT
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.
Comment 8 Danial Horton 2012-06-05 12:42:55 PDT
MC
Working
20120525113255
http://hg.mozilla.org/mozilla-central/rev/034bbdc7b9c9

Broken
20120527030515
http://hg.mozilla.org/mozilla-central/rev/133aa3a2ef0a
Comment 9 Danial Horton 2012-06-05 12:56:10 PDT
nvm that last post, i screwed up by forgetting to set incremental back to on in the 27th build.
Comment 10 Andrew McCreight [:mccr8] 2012-06-05 13:10:40 PDT
(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 Danial Horton 2012-06-05 13:15:02 PDT
Not all that strange, i also got one or 2 completely random incremental slices and then was not able to get them again
Comment 12 :Ehsan Akhgari 2012-06-05 13:16:18 PDT
(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 Danial Horton 2012-06-05 13:38:45 PDT
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 Danial Horton 2012-06-05 13:43:22 PDT
i found the cause of the random Incremental Slice;  Having the window minimised to tray.
Comment 15 Danial Horton 2012-06-05 13:44:31 PDT
Taskbar*
Comment 16 :Ehsan Akhgari 2012-06-05 13:55:26 PDT
http://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=73783bf75c4c&tochange=5199196b65ec

Time for somebody to bisect this I guess!  :-)
Comment 17 Danial Horton 2012-06-05 14:01:09 PDT
im betting something within http://hg.mozilla.org/mozilla-central/pushloghtml?changeset=12ab69851e05
Comment 18 Andrew McCreight [:mccr8] 2012-06-05 14:08:20 PDT
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
Comment 19 Andrew McCreight [:mccr8] 2012-06-05 14:10:15 PDT
I flipped javascript.options.mem.disable_explicit_compartment_gc to false, and now my GCs are all incremental.
Comment 20 :Ehsan Akhgari 2012-06-05 14:14:12 PDT
(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 Danial Horton 2012-06-05 14:18:41 PDT
good call Andrew,

Is this to be expected Bill?
Comment 22 Andrew McCreight [:mccr8] 2012-06-05 14:22:04 PDT
I think bug 758034 is supposed to fix this, or something like it.
Comment 23 Ioana (away) 2012-06-08 06:01:19 PDT
I've also seen this issue on:
Mozilla/5.0 (Windows NT 6.1; rv:15.0) Gecko/20120606 Firefox/15.0a2 (20120606042008)
Comment 24 Ioana (away) 2012-06-08 07:07:30 PDT
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.
Comment 25 Andrew McCreight [:mccr8] 2012-06-08 07:12:56 PDT
Good point.
Comment 26 Ioana (away) 2012-06-08 08:11:04 PDT
(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.
Comment 27 Bill McCloskey (:billm) 2012-06-10 16:20:08 PDT
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.
Comment 29 Graeme McCutcheon [:graememcc] 2012-06-12 03:07:36 PDT
https://hg.mozilla.org/mozilla-central/rev/828da55601e7
Comment 30 Olli Pettay [:smaug] 2012-06-12 03:10:04 PDT
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
Comment 31 Alex Keybl [:akeybl] 2012-06-15 16:06:47 PDT
(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?
Comment 32 Andrew McCreight [:mccr8] 2012-06-15 17:56:17 PDT
(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.
Comment 33 Olli Pettay [:smaug] 2012-06-16 10:50:46 PDT
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 34 Lukas Blakk [:lsblakk] use ?needinfo 2012-06-18 16:57:49 PDT
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.
Comment 35 Lukas Blakk [:lsblakk] use ?needinfo 2012-06-18 16:58:40 PDT
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.
Comment 36 Olli Pettay [:smaug] 2012-06-19 01:44:47 PDT
https://tbpl.mozilla.org/?tree=Try&rev=c929ad74c0f4
Comment 37 Olli Pettay [:smaug] 2012-06-19 02:52:06 PDT
Not looking good. Bill, is Aurora missing some other GC patches?
Comment 38 Danial Horton 2012-06-19 04:04:35 PDT
does javascript.options.mem.disable_explicit_compartment_gc;false improve things on aurora?
Comment 39 Bill McCloskey (:billm) 2012-06-19 08:31:08 PDT
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.
Comment 40 Bill McCloskey (:billm) 2012-06-26 15:55:04 PDT
We're not going to land this on Aurora. Instead, we're going to do bug 768688.
Comment 41 Lukas Blakk [:lsblakk] use ?needinfo 2012-07-18 09:16:47 PDT
[Triage Comment]
Removing tracking-firefox15 as per comment 40 - bug 768788 has been tracked and landed in 15.

Note You need to log in before you can comment on or make changes to this bug.