Note: There are a few cases of duplicates in user autocompletion which are being worked on.

leaking ro.me after page close

RESOLVED FIXED in Firefox 18

Status

()

Core
DOM
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: gwagner, Unassigned)

Tracking

unspecified
mozilla19
x86
Mac OS X
Points:
---

Firefox Tracking Flags

(firefox17 unaffected, firefox18 fixed)

Details

(Whiteboard: [MemShrink], URL)

(Reporter)

Description

5 years ago
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

5 years ago
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.
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.
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.
Summary: CC takes repeatedly 10 sec after closing ro.me → leaking ro.me after page close
Whiteboard: [MemShrink]
(Reporter)

Comment 4

5 years ago
Hm maybe I just changed to another URL. Let me try again.
(Reporter)

Comment 5

5 years ago
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
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.
But as you can see it is very effective, making CCs around 54 times faster. ;)
(Reporter)

Updated

5 years ago
status-firefox17: --- → unaffected
status-firefox18: --- → affected
status-firefox19: --- → affected

Comment 8

5 years ago
Is ro.me a WebGL thing? If so, I wonder if this leak has something to do with Bug 802834.
Oh, good point.
Depends on: 795186
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.
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED

Updated

5 years ago
status-firefox19: affected → ---
Target Milestone: --- → mozilla19
status-firefox18: affected → fixed
You need to log in before you can comment on or make changes to this bug.