Last Comment Bug 767209 - Consider changing GC slice time, or making it dynamic
: Consider changing GC slice time, or making it dynamic
Status: RESOLVED FIXED
[js:t][Snappy]
:
Product: Core
Classification: Components
Component: JavaScript Engine (show other bugs)
: unspecified
: All All
: -- normal (vote)
: mozilla17
Assigned To: Bill McCloskey (:billm)
:
Mentors:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2012-06-21 17:19 PDT by Bill McCloskey (:billm)
Modified: 2012-08-06 18:47 PDT (History)
7 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
API to allow for longer slices (4.98 KB, patch)
2012-07-27 16:36 PDT, Bill McCloskey (:billm)
terrence: review+
Details | Diff | Splinter Review
use longer slices (6.81 KB, patch)
2012-07-27 16:46 PDT, Bill McCloskey (:billm)
bugs: review+
Details | Diff | Splinter Review

Description Bill McCloskey (:billm) 2012-06-21 17:19:12 PDT
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] 2012-06-22 15:07:43 PDT
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 (:billm) 2012-07-27 16:36:31 PDT
Created attachment 646756 [details] [diff] [review]
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 (:billm) 2012-07-27 16:46:40 PDT
Created attachment 646757 [details] [diff] [review]
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] 2012-07-27 16:49:07 PDT
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] 2012-07-29 11:42:48 PDT
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] 2012-07-30 11:30:16 PDT
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] 2012-07-30 11:40:04 PDT
painting isn't the only interesting thing. Reacting asap to user input is important.
Comment 8 Bill McCloskey (:billm) 2012-07-30 12:03:16 PDT
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] 2012-07-30 12:09:55 PDT
100ms sounds quite a lot, but ok, let's try 40ms.
Comment 11 Ed Morley [:emorley] 2012-08-01 02:51:56 PDT
https://hg.mozilla.org/mozilla-central/rev/f6ebe752f7cd
Comment 12 Andrew McCreight [:mccr8] 2012-08-06 18:47:13 PDT
As may be expected, my GC_SLICE_MS looks bimodal now, with peaks of approximately even height at 10ms and 40ms.

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