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.

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

(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.

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.

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

Not without a local build that changes that constant.

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.