767209 - Consider changing GC slice time, or making it dynamic

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

We get a lot of incremental resets right now during everyday browsing. Bug 758034 should make the resets go away, although we'll still get CC_FORCED slices that are long. Gregor suggested making the slices longer, possibly based on the number of CC_FORCED slices we've had to perform in the past.

Comment 1

[Gregor Wagner [:gwagner]]

I did some benchmarking with many tabs to see how important this bug is. I measured with IGC enabled and disabled. First disabled and then enabled. Note that I already increased the slice time to 30msec but the actual pauses are around 80msec. The peak pause time increases from 1.1sec to 2.3 sec. The memory consumption also changed from 582MB to 626MB.

GC(T+808.0) Total Time: 1089.9ms, Compartments Collected: 1244, Total Compartments: 1244, MMU (20ms): 0%, MMU (50ms): 0%, Reason: SET_NEW_DOCUMENT, Nonincremental Reason: GC mode, Allocated: 582MB, +Chunks: 0, -Chunks: 0
    Totals: Begin Callback: 0.2ms, Wait Background Thread: 1.9ms, Purge: 0.6ms, Mark: 789.6ms, Mark Roots: 45.0ms, Mark Other: 27.0ms, Finalize Start Callback: 1.8ms, Sweep: 246.9ms, Sweep Compartments: 145.8ms, Sweep Object: 9.2ms, Sweep String: 2.6ms, Sweep Script: 5.8ms, Sweep Shape: 37.9ms, Discard Code: 18.5ms, Discard Analysis: 87.2ms, Discard TI: 12.6ms, Sweep Types: 47.6ms, Clear Script Analysis: 4.0ms, Finalize End Callback: 10.8ms, Deallocate: 0.6ms, End Callback: 48.3ms

GC(T+891.1) Total Time: 3624.2ms, Compartments Collected: 1328, Total Compartments: 1328, MMU (20ms): 0%, MMU (50ms): 0%, Max Pause: 2291.9ms, Nonincremental Reason: requested, Allocated: 626MB, +Chunks: 0, -Chunks: 0
    Slice: 0, Pause: 86.5 (When: 0.0ms, Reason: CC_WAITING): Begin Callback: 0.2ms, Purge: 3.2ms, Mark: 59.6ms, Mark Roots: 49.4ms, Discard Code: 20.0ms
    Slice: 1, Pause: 75.9 (When: 446.5ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.3ms, Mark: 55.1ms, Mark Roots: 44.8ms, Discard Code: 16.5ms
    Slice: 3, Pause: 72.0 (When: 968.6ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.3ms, Mark: 51.3ms, Mark Roots: 41.2ms, Discard Code: 16.5ms
    Slice: 4, Pause: 78.4 (When: 1215.1ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.4ms, Mark: 58.1ms, Mark Roots: 47.9ms, Discard Code: 15.8ms
    Slice: 5, Pause: 79.4 (When: 1586.2ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.4ms, Mark: 57.8ms, Mark Roots: 47.6ms, Discard Code: 17.1ms
    Slice: 6, Pause: 79.0 (When: 2092.6ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.4ms, Mark: 57.8ms, Mark Roots: 47.7ms, Discard Code: 16.6ms
    Slice: 7, Pause: 72.8 (When: 2510.9ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.4ms, Mark: 52.2ms, Mark Roots: 42.0ms, Discard Code: 16.3ms
    Slice: 8, Pause: 79.3 (When: 2848.9ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.4ms, Mark: 58.4ms, Mark Roots: 48.2ms, Discard Code: 16.2ms
    Slice: 9, Pause: 81.6 (When: 3076.6ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.4ms, Mark: 60.7ms, Mark Roots: 50.4ms, Discard Code: 16.3ms
    Slice: 10, Pause: 78.3 (When: 3318.3ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.4ms, Mark: 58.0ms, Mark Roots: 47.9ms, Discard Code: 15.7ms
    Slice: 11, Pause: 78.9 (When: 3654.1ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.4ms, Mark: 57.6ms, Mark Roots: 47.5ms, Discard Code: 16.7ms
    Slice: 12, Pause: 80.6 (When: 3990.9ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.4ms, Mark: 59.2ms, Mark Roots: 49.0ms, Discard Code: 16.8ms
    Slice: 14, Pause: 72.5 (When: 4562.5ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.5ms, Mark: 51.6ms, Mark Roots: 41.5ms, Discard Code: 16.3ms
    Slice: 15, Pause: 71.7 (When: 4752.0ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.3ms, Mark: 51.8ms, Mark Roots: 41.6ms, Discard Code: 15.7ms
    Slice: 16, Pause: 73.0 (When: 4943.0ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.3ms, Mark: 52.7ms, Mark Roots: 42.5ms, Discard Code: 16.0ms
    Slice: 17, Pause: 77.8 (When: 5298.6ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.4ms, Mark: 56.8ms, Mark Roots: 46.7ms, Discard Code: 16.4ms
    Slice: 18, Pause: 71.8 (When: 5683.5ms, Reason: INTER_SLICE_GC, Reset: compartment change): Purge: 0.3ms, Mark: 51.6ms, Mark Roots: 41.3ms, Discard Code: 15.8ms
    Slice: 19, Pause: 2291.9 (When: 5879.0ms, Reason: CC_FORCED, Reset: requested): Begin Callback: 0.2ms, Purge: 0.5ms, Mark: 1655.0ms, Mark Roots: 82.7ms, Mark Other: 60.5ms, Finalize Start Callback: 4.2ms, Sweep: 508.6ms, Sweep Compartments: 284.9ms, Sweep Object: 30.9ms, Sweep String: 7.4ms, Sweep Script: 11.2ms, Sweep Shape: 80.8ms, Discard Code: 31.3ms, Discard Analysis: 170.4ms, Discard TI: 21.2ms, Sweep Types: 99.7ms, Clear Script Analysis: 8.4ms, Finalize End Callback: 25.7ms, Deallocate: 1.9ms, End Callback: 122.4ms
    Totals: Begin Callback: 0.3ms, Wait Background Thread: 0.2ms, Purge: 9.7ms, Mark: 2625.8ms, Mark Roots: 859.9ms, Mark Other: 60.5ms, Finalize Start Callback: 4.2ms, Sweep: 508.6ms, Sweep Compartments: 284.9ms, Sweep Object: 30.9ms, Sweep String: 7.4ms, Sweep Script: 11.2ms, Sweep Shape: 80.8ms, Discard Code: 311.9ms, Discard Analysis: 170.4ms, Discard TI: 21.2ms, Sweep Types: 99.7ms, Clear Script Analysis: 8.4ms, Finalize End Callback: 25.7ms, Deallocate: 1.9ms, End Callback: 122.4ms

Comment 2

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Attachment: API to allow for longer slices

This patch adds a parameter to IncrementalGC that allows the slice time to be specified.

Comment 3

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Attachment: use longer slices

This patch causes GC slices triggered by the inter-slice GC timer to run for longer--40ms instead of 10ms. The inter-slice timer only fires if there hasn't been any painting for the last 100ms, so it shouldn't happen during animations or anything else that's very sensitive to latency.

Longer slices are good because they make the GC finish faster. There are certain events, like heavy allocation, that cause us to turn an incremental GC into a non-incremental GC. The faster the GC finishes, the less likely it is to be affected by one of these events.

Comment 4

[Terrence Cole [:terrence]]

Comment on attachment 646756 [details] [diff] [review]
API to allow for longer slices

Review of attachment 646756 [details] [diff] [review]:
-----------------------------------------------------------------

::: js/src/gc/Statistics.cpp
@@ +25,5 @@
>  namespace js {
>  namespace gcstats {
>  
> +/* Except for the first and last, slices of less than 42ms are not reported. */
> +static const int64_t SLICE_MIN_REPORT_TIME = 42 * PRMJ_USEC_PER_MSEC;

Good idea, now that we have a separate pref for the JSON output.

Comment 5

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 646757 [details] [diff] [review]
use longer slices

Is 40ms a bit much if there is pending user input?
Could we try 25ms?

Comment 6

[Terrence Cole [:terrence]]

This is only for slices that happen because we haven't had a frame draw in >100ms.  A 15ms difference isn't going to be noticeable in either direction in this case.

Comment 7

[Olli Pettay [:smaug][[e-mail]]]

painting isn't the only interesting thing. Reacting asap to user input is important.

Comment 8

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

According to this stackoverflow thread, response time of less than 100ms isn't noticeable to users:
http://stackoverflow.com/questions/536300/what-is-the-shortest-perceivable-application-response-delay

A GC delay of 40ms still gives us 60ms to do whatever processing is needed to respond to an incoming event. Also keep in mind that there's a balance here. If we don't finish the GC fast enough, then it may get switched to a non-incremental GC (if a CC is forced, say), and then we'll take a lot longer than 40ms.

So I'd rather stay at 40ms, but I'll defer if you still are concerned, Olli.

I also had an idea to make this work better, although it will take some time. We can call some sort of callback after every 10ms of GC. It would check if there are any events pending. If there are, we would return immediately. Otherwise we would continue collecting up to, say, 100ms or something. I'll file a bug to do this, but I'd like to land this more immediate fix now.

Comment 9

[Olli Pettay [:smaug][[e-mail]]]

100ms sounds quite a lot, but ok, let's try 40ms.

Comment 10

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/f6ebe752f7cd

Comment 11

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/f6ebe752f7cd

Comment 12

[Andrew McCreight [:mccr8]]

As may be expected, my GC_SLICE_MS looks bimodal now, with peaks of approximately even height at 10ms and 40ms.