800488 - leaking ro.me after page close

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[Gregor Wagner [:gwagner]]

I see constant 10 sec CC pauses with the current nightly.

My testcase: run ro.me for a min and close the tab.

CC(T+311.5) duration: 10344ms, suspected: 150, visited: 8224 RCed and 8237124 GCed, collected: 73 RCed and 4 GCed (77 waiting for GC)
ForgetSkippable 2 times before CC, min: 1 ms, max: 2 ms, avg: 2 ms, total: 4 ms, removed: 442

CC(T+364.0) duration: 10312ms, suspected: 294, visited: 8348 RCed and 8237116 GCed, collected: 23 RCed and 0 GCed (100 waiting for GC)
ForgetSkippable 26 times before CC, min: 0 ms, max: 2 ms, avg: 0 ms, total: 12 ms, removed: 4663

CC(T+381.8) duration: 10387ms, suspected: 277, visited: 12516 RCed and 8237103 GCed, collected: 105 RCed and 0 GCed (205 waiting for GC)
ForgetSkippable 5 times before CC, min: 1 ms, max: 7 ms, avg: 2 ms, total: 14 ms, removed: 40272

GC(T+382.4) Total Time: 551.8ms, Compartments Collected: 159, Total Compartments: 159, MMU (20ms): 0%, MMU (50ms): 0%, SCC Sweep Total: 43.2ms, SCC Sweep Max Pause: 37.9ms, Max Pause: 480.6ms, Allocated: 673MB, +Chunks: 6, -Chunks: 0
    Slice: 0, Pause: 34.9 (When: 0.0ms, Reason: PAGE_HIDE): Mark: 33.1ms, Mark Discard Code: 1.3ms, Mark Roots: 32.7ms
    Slice: 4, Pause: 480.6 (When: 90.3ms, Reason: REFRESH_FRAME): Mark: 434.9ms, Mark Gray: 434.6ms, Mark Gray and Weak: 0.2ms, Sweep: 44.8ms, Sweep Compartments: 4.7ms, Sweep Tables: 2.3ms, Sweep Object: 36.2ms, Sweep String: 1.8ms, Sweep Script: 0.3ms, Sweep Discard Code: 0.6ms, Discard Analysis: 1.7ms, Discard TI: 0.5ms, Sweep Types: 1.0ms, Clear Script Analysis: 0.2ms, Finalize End Callback: 0.9ms
    Slice: 7, Pause: 0.1 (When: 593.0ms, Reason: REFRESH_FRAME): 
    Totals: Mark: 494.5ms, Mark Discard Code: 1.3ms, Mark Roots: 32.7ms, Mark Gray: 434.6ms, Mark Gray and Weak: 0.2ms, Sweep: 48.6ms, Sweep Atoms: 4.1ms, Sweep Compartments: 4.7ms, Sweep Tables: 2.3ms, Sweep Object: 36.2ms, Sweep String: 1.8ms, Sweep Script: 0.3ms, Sweep Shape: 3.8ms, Sweep Discard Code: 0.6ms, Discard Analysis: 1.7ms, Discard TI: 0.5ms, Sweep Types: 1.0ms, Clear Script Analysis: 0.2ms, Finalize End Callback: 0.9ms

CC(T+394.9) duration: 10513ms, suspected: 17743, visited: 43345 RCed and 8240013 GCed, collected: 35262 RCed and 2889 GCed (38151 waiting for GC)
ForgetSkippable 2 times before CC, min: 5 ms, max: 8 ms, avg: 6 ms, total: 13 ms, removed: 19349

GC(T+399.9) Total Time: 492.1ms, Compartments Collected: 158, Total Compartments: 158, MMU (20ms): 0%, MMU (50ms): 0%, SCC Sweep Total: 5.1ms, SCC Sweep Max Pause: 1.5ms, Max Pause: 437.6ms, Allocated: 641MB, +Chunks: 0, -Chunks: 5
    Slice: 0, Pause: 22.0 (When: 0.0ms, Reason: CC_WAITING): Mark: 20.8ms, Mark Discard Code: 0.7ms, Mark Roots: 20.5ms
    Slice: 3, Pause: 437.6 (When: 270.2ms, Reason: INTER_SLICE_GC): Mark: 431.0ms, Mark Gray: 430.8ms, Mark Gray and Weak: 0.2ms, Sweep: 6.1ms, Sweep Compartments: 3.9ms, Sweep Tables: 2.1ms, Sweep Object: 0.6ms, Sweep String: 0.2ms, Sweep Script: 0.3ms, Sweep Discard Code: 0.6ms, Discard Analysis: 1.2ms, Sweep Types: 0.9ms, Clear Script Analysis: 0.2ms, Finalize End Callback: 0.8ms
    Slice: 6, Pause: 0.1 (When: 1006.3ms, Reason: INTER_SLICE_GC): 
    Totals: Mark: 478.4ms, Mark Discard Code: 0.7ms, Mark Roots: 20.5ms, Mark Gray: 430.8ms, Mark Gray and Weak: 0.2ms, Sweep: 8.1ms, Sweep Atoms: 2.6ms, Sweep Compartments: 3.9ms, Sweep Tables: 2.1ms, Sweep Object: 0.6ms, Sweep String: 0.2ms, Sweep Script: 0.3ms, Sweep Shape: 1.9ms, Sweep Discard Code: 0.6ms, Discard Analysis: 1.2ms, Sweep Types: 0.9ms, Clear Script Analysis: 0.2ms, Finalize End Callback: 0.8ms

CC(T+410.4) duration: 10373ms, suspected: 246, visited: 8121 RCed and 8237121 GCed, collected: 58 RCed and 3 GCed (61 waiting for GC)
ForgetSkippable 3 times before CC, min: 0 ms, max: 2 ms, avg: 1 ms, total: 3 ms, removed: 35377

CC(T+442.5) duration: 10391ms, suspected: 223, visited: 12560 RCed and 8237106 GCed, collected: 57 RCed and 0 GCed (118 waiting for GC)
ForgetSkippable 9 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 3 ms, removed: 1617

.. and so on

It's hard to file a bug with all the 10sec freezes :)

Comment 1

[Olli Pettay [:smaug][[e-mail]] (holiday -> Aug30)]

Andrew, could this be the same problem what bill had with his demo?
Looks like there is lots of GCed stuff in the CC.

Gregor, cc log would be nice.

Comment 2

[Andrew McCreight [:mccr8]]

This suggests we're leaking ro.me after we close the page.

A previous bug, bug 763730, was about getting a single long CC when we closed the page.  That was fixed by compartment merging, but compartment merging intentionally only is done a few times after a tab close, so then because we're leaking, it fails and we get long CCs again.

Comment 3

[Andrew McCreight [:mccr8]]

No, in Bill's case, he didn't close the tab, so the page was still in the BFCache.  My understanding is that with a tab close, the page should get thrown out right away.

Comment 4

[Gregor Wagner [:gwagner]]

Hm maybe I just changed to another URL. Let me try again.

Comment 5

[Gregor Wagner [:gwagner]]

Ok I definitely closed it.

The strange thing is that I see short and long CC pauses afterwards.

CC(T+118.5) duration: 10110ms, suspected: 522, visited: 13728 RCed and 8236804 GCed, collected: 1093 RCed and 2144 GCed (3237 waiting for GC)
ForgetSkippable 3 times before CC, min: 1 ms, max: 2 ms, avg: 1 ms, total: 5 ms, removed: 3956

CC(T+121.5) duration: 183ms, suspected: 386, visited: 13236 RCed and 4177 merged GCed, collected: 595 RCed and 2174 GCed (2769 waiting for GC)
ForgetSkippable 3 times before CC, min: 1 ms, max: 2 ms, avg: 1 ms, total: 5 ms, removed: 2381

CC(T+147.2) duration: 10202ms, suspected: 598, visited: 16215 RCed and 8263826 GCed, collected: 3535 RCed and 29609 GCed (33144 waiting for GC)
ForgetSkippable 9 times before CC, min: 0 ms, max: 2 ms, avg: 0 ms, total: 7 ms, removed: 4208

Comment 6

[Andrew McCreight [:mccr8]]

The short ones are ones where the compartments are merged.  I put in code to ensure we don't merge too much, because it can be leaky.

Comment 7

[Andrew McCreight [:mccr8]]

But as you can see it is very effective, making CCs around 54 times faster. ;)

Comment 8

[Olli Pettay [:smaug][[e-mail]] (holiday -> Aug30)]

Is ro.me a WebGL thing? If so, I wonder if this leak has something to do with Bug 802834.

Comment 9

[Andrew McCreight [:mccr8]]

Oh, good point.

Comment 10

[Benoit Jacob [:bjacob] (mostly away)]

This is fixed by https://hg.mozilla.org/integration/mozilla-inbound/rev/15b7770dcfcc , in my limited testing which consists in loading RO.ME, letting it run for a minute, opening a new tab with about:memory, closing the RO.ME tab, and clicking GC and CC (but NOT 'minimize memory usage') a few times in about:memory and verifying that all webgl metrics disappear.