Alon Zakai (:azakai) Reporter
	Description • 12 years ago

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.

	Andrew McCreight [:mccr8]
	Comment 1 • 12 years ago

The large pauses are both caused by Sweep Object.

	Andrew McCreight [:mccr8]
	Comment 2 • 12 years ago

...which is about 1.8 seconds each time.

	Alon Zakai (:azakai) Reporter
	Comment 3 • 12 years ago

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

	Bill McCloskey [inactive unless it's an emergency] (:billm)
	Comment 4 • 12 years ago

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.

	Alon Zakai (:azakai) Reporter
	Comment 5 • 12 years ago

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.

	Steve Fink [:sfink] [:s:] Assignee
	Comment 6 • 12 years ago

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.

	Steve Fink [:sfink] [:s:] Assignee
	Comment 7 • 12 years ago

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

	Steve Fink [:sfink] [:s:] Assignee
	Comment 8 • 12 years ago

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.

	Alon Zakai (:azakai) Reporter
	Comment 9 • 12 years ago

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

	Alon Zakai (:azakai) Reporter
	Comment 10 • 12 years ago

Confirmed, thanks sfink!

	Steve Fink [:sfink] [:s:] Assignee
	Comment 11 • 12 years ago

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.