788205 - Big new GC pauses in BananaBread

Status: RESOLVED DUPLICATE of bug 789295

(Core :: JavaScript Engine, defect)

Description

[Alon Zakai (:azakai)]

BananaBread creates almost no garbage and used to have no noticeable pauses. However since last week a change for the worst happened on Nightly. Here are two example pauses:

GC(T+127.0) Total Time: 1845.6ms, Compartments Collected: 171, Total Compartments: 171, MMU (20ms): 0%, MMU (50ms): 0%, SCC Sweep Total: 1803.2ms, SCC Sweep Max Pause: 1797.5ms, Max Pause: 1807.9ms, Allocated: 31MB, +Chunks: 3, -Chunks: 2
    Slice: 0, Pause: 13.3 (When: 0.0ms, Reason: MAYBEGC): Mark: 9.8ms, Mark Discard Code: 3.2ms, Mark Roots: 9.1ms, Mark Types: 4.2ms
    Slice: 4, Pause: 1807.9 (When: 281.0ms, Reason: REFRESH_FRAME): Mark: 3.3ms, Mark Gray: 3.2ms, Finalize Start Callback: 0.1ms, Sweep: 1804.3ms, Sweep Compartments: 6.7ms, Sweep Tables: 2.1ms, Sweep Object: 1796.2ms, Sweep Script: 0.1ms, Sweep Discard Code: 3.1ms, Discard Analysis: 0.9ms, Sweep Types: 0.2ms, Clear Script Analysis: 0.2ms, Finalize End Callback: 0.4ms
    Slice: 7, Pause: 0.2 (When: 2231.6ms, Reason: REFRESH_FRAME): 
    Totals: Mark: 34.3ms, Mark Discard Code: 3.2ms, Mark Roots: 9.1ms, Mark Types: 4.2ms, Mark Gray: 3.2ms, Finalize Start Callback: 0.1ms, Sweep: 1806.4ms, Sweep Atoms: 0.5ms, Sweep Compartments: 6.7ms, Sweep Tables: 2.1ms, Sweep Object: 1796.2ms, Sweep Script: 0.1ms, Sweep Shape: 2.1ms, Sweep Discard Code: 3.1ms, Discard Analysis: 0.9ms, Sweep Types: 0.2ms, Clear Script Analysis: 0.2ms, Finalize End Callback: 0.4ms

CC(T+128.1) duration: 4ms, suspected: 65, visited: 446 RCed and 688 GCed, collected: 0 RCed and 0 GCed (0 waiting for GC)
ForgetSkippable 7 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 5 ms, removed: 640

[..]

GC(T+260.0) Total Time: 1533.0ms, Compartments Collected: 171, Total Compartments: 171, MMU (20ms): 0%, MMU (50ms): 0%, SCC Sweep Total: 1511.4ms, SCC Sweep Max Pause: 1505.4ms, Max Pause: 1513.6ms, Allocated: 39MB, +Chunks: 10, -Chunks: 4
    Slice: 0, Pause: 10.1 (When: 0.0ms, Reason: MAYBEGC): Mark: 9.2ms, Mark Discard Code: 0.8ms, Mark Roots: 4.0ms, Mark Types: 2.0ms
    Slice: 2, Pause: 1513.6 (When: 149.0ms, Reason: REFRESH_FRAME): Mark: 1.2ms, Mark Gray: 1.1ms, Sweep: 1512.2ms, Sweep Compartments: 5.7ms, Sweep Tables: 2.0ms, Sweep Object: 1505.2ms, Sweep String: 0.2ms, Sweep Script: 0.1ms, Sweep Discard Code: 2.5ms, Discard Analysis: 0.8ms, Sweep Types: 0.3ms, Clear Script Analysis: 0.2ms, Finalize End Callback: 0.4ms
    Slice: 5, Pause: 0.1 (When: 1721.6ms, Reason: REFRESH_FRAME): 
    Totals: Mark: 16.8ms, Mark Discard Code: 0.8ms, Mark Roots: 4.0ms, Mark Types: 2.0ms, Mark Gray: 1.1ms, Sweep: 1514.4ms, Sweep Atoms: 0.5ms, Sweep Compartments: 5.7ms, Sweep Tables: 2.0ms, Sweep Object: 1505.2ms, Sweep String: 0.2ms, Sweep Script: 0.1ms, Sweep Shape: 2.2ms, Sweep Discard Code: 2.5ms, Discard Analysis: 0.8ms, Sweep Types: 0.3ms, Clear Script Analysis: 0.2ms, Finalize End Callback: 0.4ms

CC(T+260.4) duration: 8ms, suspected: 305, visited: 651 RCed and 702 GCed, collected: 35 RCed and 14 GCed (49 waiting for GC)
ForgetSkippable 22 times before CC, min: 0 ms, max: 3 ms, avg: 0 ms, total: 16 ms, removed: 1980

These pauses are on a linux machine with no addons and no extensions, latest Nightly.

STR:

1. Load https://developer.mozilla.org/demos/detail/bananabread
2. Click "launch demo"
3. Click "Lava Chamber"
4. Click "Low Res" (doesn't matter though, other button is ok too)
5. Walk around for a while (wasd+mouse+space to jump). Constantly moving and jumping makes the pauses noticeable.

Comment 1

[Andrew McCreight [:mccr8]]

The large pauses are both caused by Sweep Object.

Comment 2

[Andrew McCreight [:mccr8]]

...which is about 1.8 seconds each time.

Comment 3

[Alon Zakai (:azakai)]

I verified that this is not an issue on Aurora which branched last week - so must be something that landed after the branch.

Comment 4

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

Steve, could this be related to the recent typed array changes? That added a finalizer that might be causing us to spend more time sweeping.

Comment 5

[Alon Zakai (:azakai)]

The typed array changes sound like a plausible cause here. They are recent, and indeed the pauses are worst in the biggest level which creates the most temporary tiny arrays. sfink did mention to me that this might be an issue, and we talked about measuring in BananaBread, but perhaps the measurements were not in the biggest level where this is noticeable.

Comment 6

[Steve Fink [:sfink] [:s:]]

Unfortunately, I never did that measurement. It slipped my mind when I was in the middle of other stuff. There's also a slight talos regression that appears to result from those same two patchsets, so they would seem to be a very likely culprit. I'll try BananaBread on the current tree with and without those changes.

Comment 7

[Steve Fink [:sfink] [:s:]]

Yes, I was definitely able to reproduce the change by backing out bug 720949 and bug 785167. (Current tip: several pauses in the 700-1800ms range, almost all time in sweep. Current tip with those bugs backed out: max pause of about 30ms.)

Comment 8

[Steve Fink [:sfink] [:s:]]

I tried running BananaBread with my patch for bug 789295 included, and the pauses seemed to be gone. I'd appreciate it if someone else could confirm.

Comment 9

[Alon Zakai (:azakai)]

I tried to confirm now but BananaBread is broken on nightly due to bug 797173. Will confirm when possible.

Comment 10

[Alon Zakai (:azakai)]

Confirmed, thanks sfink!

Comment 11

[Steve Fink [:sfink] [:s:]]

Can we get this off the tracking list? Was I supposed to mark it status-firefox18=fixed when resolving as a duplicate? I'll do that now, given Alon's confirmation above.