1202151 - Frequent 30-60 second GC pauses when CC_FORCED intersects USER_INACTIVE, PERIODIC_FULL, or other ongoing IGC

Status: RESOLVED INCOMPLETE

(Core :: JavaScript: GC, defect)

Description

[Terrence Cole [:terrence]]

The IGC is going along nicely when the CC comes along and kills my session for 37 seconds.

GC(T+847632.6) Max Pause: 37401.1ms, Total Time: 38331.0ms, Zones Collected: 592, Total Zones: 592, Total Compartments: 2897, Minor GCs: 13, Store Buffer Overflows: 0, MMU (20ms): 0%, MMU (50ms): 0%, SCC Sweep Total: 341.1ms, SCC Sweep Max Pause: 341.1ms, Allocated: 1274MB, +Chunks: 0, -Chunks: 0
    Slice: 0, Pause: 126.2 (When: 0.0ms, Reason: USER_INACTIVE, Budget: 10ms): Mark Discard Code: 7.2ms, Relazify Functions: 35.6ms, Purge: 1.0ms, Mark: 76.1ms, Mark Roots: 43.1ms, Buffer Gray Roots: 28.9ms, Mark Rooters: 1.3ms, Mark Runtime-wide Data: 3.8ms, Mark Embedding: 1.8ms, Mark Compartments: 6.9ms, Unmark: 32.8ms, Minor GCs to Evict Nursery: 0.9ms, Mark Roots: 0.4ms
    Slice: 1, Pause: 40.2 (When: 226.2ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.9ms
    Slice: 2, Pause: 40.2 (When: 366.5ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.1ms, Minor GCs to Evict Nursery: 0.9ms, Mark Roots: 0.4ms, Mark Rooters: 0.1ms
    Slice: 3, Pause: 40.2 (When: 507.1ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.4ms, Minor GCs to Evict Nursery: 0.6ms, Mark Roots: 0.4ms, Mark Rooters: 0.1ms
    Slice: 4, Pause: 40.2 (When: 647.3ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.9ms
    Slice: 5, Pause: 40.2 (When: 787.6ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.4ms, Minor GCs to Evict Nursery: 0.6ms, Mark Roots: 0.4ms
    Slice: 6, Pause: 40.2 (When: 927.9ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.4ms, Minor GCs to Evict Nursery: 0.6ms, Mark Roots: 0.4ms, Mark Rooters: 0.1ms
    Slice: 7, Pause: 40.2 (When: 1068.3ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 40.0ms
    Slice: 8, Pause: 40.2 (When: 1208.5ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.5ms, Minor GCs to Evict Nursery: 0.5ms, Mark Roots: 0.4ms, Mark Rooters: 0.1ms
    Slice: 9, Pause: 40.2 (When: 1348.7ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.4ms, Minor GCs to Evict Nursery: 0.6ms, Mark Roots: 0.4ms, Mark Rooters: 0.1ms
    Slice: 10, Pause: 40.2 (When: 1489.6ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.3ms, Minor GCs to Evict Nursery: 0.7ms, Mark Roots: 0.5ms, Mark Rooters: 0.1ms
    Slice: 11, Pause: 40.2 (When: 1630.0ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.9ms
    Slice: 12, Pause: 40.2 (When: 1770.3ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.4ms, Minor GCs to Evict Nursery: 0.6ms, Mark Roots: 0.4ms
    Slice: 13, Pause: 40.3 (When: 1910.6ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.9ms
    Slice: 14, Pause: 40.2 (When: 2051.1ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.9ms
    Slice: 15, Pause: 40.2 (When: 2191.7ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.4ms, Minor GCs to Evict Nursery: 0.6ms, Mark Roots: 0.4ms, Mark Rooters: 0.1ms
    Slice: 16, Pause: 40.1 (When: 2332.2ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.4ms, Minor GCs to Evict Nursery: 0.6ms, Mark Roots: 0.4ms, Mark Rooters: 0.1ms
    Slice: 17, Pause: 40.2 (When: 2472.3ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.0ms, Minor GCs to Evict Nursery: 0.9ms, Mark Roots: 0.4ms, Mark Rooters: 0.1ms
    Slice: 18, Pause: 40.2 (When: 2612.4ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.9ms
    Slice: 19, Pause: 40.2 (When: 2752.8ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.4ms, Minor GCs to Evict Nursery: 0.6ms, Mark Roots: 0.4ms, Mark Rooters: 0.1ms
    Slice: 20, Pause: 40.2 (When: 2893.1ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.9ms
    Slice: 21, Pause: 37401.1 (When: 2933.4ms, Reason: CC_FORCED, Budget: unlimited): Relazify Functions: 816.3ms, Purge: 6.3ms, Mark: 20288.4ms, Mark Roots: 329.1ms, Mark Cross Compartment Wrappers: 2.1ms, Mark Rooters: 31.2ms, Mark Runtime-wide Data: 90.8ms, Mark Embedding: 41.8ms, Mark Compartments: 155.7ms, Unmark: 752.4ms, Mark Delayed: 0.8ms, Sweep: 10277.9ms, Mark During Sweeping: 5636.4ms, Mark Incoming Black Pointers: 1.9ms, Mark Weak: 2768.4ms, Mark Incoming Gray Pointers: 1.5ms, Mark Gray: 2664.7ms, Mark Gray and Weak: 199.0ms, Finalize Start Callback: 86.9ms, Sweep Atoms: 656.1ms, Sweep Compartments: 2949.3ms, Sweep Discard Code: 190.8ms, Sweep Inner Views: 4.0ms, Sweep Cross Compartment Wrappers: 391.6ms, Sweep Base Shapes: 121.8ms, Sweep Initial Shapes: 334.7ms, Sweep Type Objects: 336.3ms, Sweep Breakpoints: 0.5ms, Sweep Regexps: 16.1ms, Sweep Miscellaneous: 149.9ms, Sweep type information: 2664.4ms, Sweep type tables and compilations: 1.6ms, Free type arena: 1.2ms, Sweep Object: 46.9ms, Sweep String: 18.7ms, Sweep Script: 262.2ms, Sweep Shape: 537.6ms, Sweep JIT code: 4.2ms, Finalize End Callback: 197.4ms, Deallocate: 53.3ms, Compact: 5986.7ms, Compact Move: 68.2ms, Compact Update: 3707.1ms, Mark Roots: 932.1ms, Mark Cross Compartment Wrappers: 5.2ms, Mark Rooters: 4.2ms, Mark Runtime-wide Data: 179.1ms, Mark Embedding: 42.8ms, Compact Update Cells: 2138.2ms, End Callback: 0.5ms, Minor GCs to Evict Nursery: 0.6ms
    Totals: 

And it cuts off here. A second example:

GC(T+847883.2) Max Pause: 51353.2ms, Total Time: 56053.6ms, Zones Collected: 592, Total Zones: 592, Total Compartments: 2876, Minor GCs: 126, Store Buffer Overflows: 22, MMU (20ms): 0%, MMU (50ms): 0%, SCC Sweep Total: 930.1ms, SCC Sweep Max Pause: 669.2ms, Allocated: 1288MB, +Chunks: 5, -Chunks: 0
    Slice: 0, Pause: 144.8 (When: 0.0ms, Reason: PERIODIC_FULL_GC, Budget: 20ms): Mark Discard Code: 22.5ms, Relazify Functions: 35.0ms, Purge: 1.9ms, Mark: 78.2ms, Mark Roots: 45.3ms, Buffer Gray Roots: 29.9ms, Mark Rooters: 1.5ms, Mark Runtime-wide Data: 4.0ms, Mark Embedding: 1.9ms, Mark Compartments: 7.7ms, Unmark: 32.8ms, Minor GCs to Evict Nursery: 1.9ms, Mark Roots: 0.4ms, Mark Rooters: 0.1ms
    Slice: 1, Pause: 20.2 (When: 209.8ms, Reason: REFRESH_FRAME, Budget: 20ms): Mark: 19.4ms, Minor GCs to Evict Nursery: 0.6ms, Mark Roots: 0.4ms
    Slice: 2, Pause: 40.2 (When: 329.9ms, Reason: INTER_SLICE_GC, Budget: 40ms): Mark: 39.4ms, Minor GCs to Evict Nursery: 0.6ms, Mark Roots: 0.4ms

This one cuts off even sooner. Not sure how to get the full logs. I assume this is the same issue though.

Comment 1

[Andrew McCreight [:mccr8]]

That's pretty weird. Why is the GC taking 20 seconds to mark?

Comment 2

[Terrence Cole [:terrence]]

(In reply to Andrew McCreight [:mccr8] from comment #1)
> That's pretty weird. Why is the GC taking 20 seconds to mark?

My current heap is 4.5GiB. It's slow, but not that unreasonable.

Comment 3

[Andrew McCreight [:mccr8]]

Well, NS_MAX_CC_LOCKEDOUT_TIME is set to 15 seconds, so that means we've been trying to CC for 15 seconds without success. If each of your GCs is taking around 35 seconds (or maybe more) then I don't really know how we can handle that well.

Comment 4

[Terrence Cole [:terrence]]

Ah, we do handle that case, however! Is there a knob I can tweak locally to make that time longer?

Comment 5

[Andrew McCreight [:mccr8]]

Not without a local build that changes that constant.

Comment 6

[Terrence Cole [:terrence]]

Andrew has since upped the limit to 30s and I found the actual 30s worth of overhead was happening later in sweeping. This last was cleaned up by incremental sweeping of XPConnect. I think we're probably good here.