851933 - long sweep times (sweeping is not incremental?)

Status: RESOLVED INCOMPLETE

(Core :: JavaScript Engine, defect)

Description

[Andreas Gal :gal]

GC(T+6999.8) Total Time: 186.1ms, Compartments Collected: 243, Total Compartments: 243, Total Zones: 243, MMU (20ms): 31%, MMU (50ms): 38%, SCC Sweep Total: 11.4ms, SCC Sweep Max Pause: 2.2ms, Max Pause: 13.7ms, Allocated: 90MB, +Chunks: 1, -Chunks: 0
    Slice: 0, Pause: 13.7 (When: 0.0ms, Reason: FULL_GC_TIMER): Mark Discard Code: 2.9ms, Mark: 10.0ms, Mark Roots: 9.7ms, Mark Types: 0.2ms
    Slice: 17, Pause: 10.2 (When: 407.4ms, Reason: REFRESH_FRAME): Sweep: 10.0ms, Mark During Sweeping: 0.2ms, Finalize Start Callback: 4.7ms, Sweep Atoms: 2.1ms, Sweep Compartments: 0.2ms, Sweep Tables: 0.1ms, Finalize End Callback: 1.0ms, Deallocate: 1.2ms
    Totals: Mark Discard Code: 2.9ms, Mark: 74.2ms, Mark Roots: 9.7ms, Mark Types: 0.2ms, Mark Delayed: 0.4ms, 

Sweep: 105.1ms, 
===============

Mark During Sweeping: 13.3ms, Mark Weak: 1.5ms, Mark Gray: 10.6ms, Mark Gray and Weak: 1.0ms, Finalize Start Callback: 70.2ms, Sweep Atoms: 2.1ms, Sweep Compartments: 10.7ms, Sweep Discard Code: 1.9ms, Sweep Tables: 2.7ms, Sweep Cross Compartment Wrappers: 0.3ms, Sweep Base Shapes: 1.1ms, Sweep Intital Shapes: 0.8ms, Sweep Type Objects: 0.3ms, Discard Analysis: 5.9ms, Discard TI: 3.8ms, Sweep Types: 1.5ms, Clear Script Analysis: 0.5ms, Sweep Object: 0.6ms, Sweep String: 0.1ms, Sweep Script: 0.4ms, Sweep Shape: 1.8ms, Finalize End Callback: 1.3ms, Deallocate: 1.2ms

I am using http://people.mozilla.org/~gal/gc.html to experiment with this. In this particular case I was accessing document.bgColor very frequently, which should create a lot of external string garbage. External strings and code are swept in the foreground only. My best guess is that thats what takes long. We should send sliced up chunks of the set of external strings to the main thread from the background thread instead.

Comment 1

[Andreas Gal :gal]

Just as a side note, I can reproduce similar sweep times by closing a bugzilla tab. The cause might be different though.

Comment 2

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

The most pertinent number to look at in the GC statistics is "Max Pause", which is the length of the longest GC slice. In this GC, it's 13.7ms. During animations, our target is 10ms, so we're doing pretty well here.

Regarding the 100ms number: when I said on Friday that sweeping is not incremental, I was oversimplifying. The more correct statement is "sweeping is not incremental for JSObjects within a single zone." So although the total time for sweeping is 105ms in this GC, it's actually broken up into multiple slices because there are multiple zones. Also, in this GC, sweeping objects doesn't cost us anything anyway (it's 0.6ms of the total). External strings are finalized incrementally in the foreground. However, we only spend 0.1ms on that anyway.

Most of the sweep time is spent in "Finalize Start Callback," which takes 70ms (and, again, is broken into multiple slices). That seems quite high to me. It's code we run in xpconnect. Looking at my own GCs, I see a lot of time there too. It's probably not a big deal because it apparently doesn't affect pause times, but it's worth looking into.

(On Feb 1, I lost the ability to watch people's GC times at this granularity because /somebody/ freaked out about the privacy implications of the GC collector addon and the privacy team forced me to stop collecting and delete all the data after 6 months. So it's much harder to track down these sorts of regressions now.)

Comment 3

[Andreas Gal :gal]

Lets get the privacy team involved on restoring that ability for you, with the proper privacy magic.

Try the page above. You can see pretty substantial pause times in the graph in the 100ms range. Something is hogging the MT for sure. It might not be what I thought it is, but something is.

Comment 4

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

What setting are you using on the page?