Big new GC pauses in BananaBread

RESOLVED DUPLICATE of bug 789295

Status

()

Core
JavaScript Engine
RESOLVED DUPLICATE of bug 789295
6 years ago
2 years ago

People

(Reporter: azakai, Assigned: sfink)

Tracking

(Blocks: 1 bug, {regression})

unspecified
x86
Linux
regression
Points:
---

Firefox Tracking Flags

(firefox18+ fixed)

Details

(Whiteboard: [js:p1:fx18][games:p1])

(Reporter)

Description

6 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.
(Reporter)

Updated

6 years ago
Blocks: 710398
Keywords: regression
The large pauses are both caused by Sweep Object.
...which is about 1.8 seconds each time.
(Reporter)

Comment 3

6 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.
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.
Keywords: regressionwindow-wanted
(Reporter)

Comment 5

6 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.
(Assignee)

Comment 6

6 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.
(Assignee)

Comment 7

6 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.)
tracking-firefox18: --- → ?
tracking-firefox18: ? → +
Whiteboard: [js:p1:fx18]

Updated

6 years ago
Whiteboard: [js:p1:fx18] → [js:p1:fx18][games:p1]
(Assignee)

Updated

6 years ago
Assignee: general → sphink
(Assignee)

Comment 8

6 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.
Status: NEW → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → DUPLICATE
Duplicate of bug: 789295
(Reporter)

Comment 9

6 years ago
I tried to confirm now but BananaBread is broken on nightly due to bug 797173. Will confirm when possible.
(Reporter)

Comment 10

6 years ago
Confirmed, thanks sfink!
(Assignee)

Comment 11

5 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.
status-firefox18: --- → fixed
Keywords: regressionwindow-wanted
You need to log in before you can comment on or make changes to this bug.