Last Comment Bug 800488 - leaking ro.me after page close
: leaking ro.me after page close
Status: RESOLVED FIXED
[MemShrink]
:
Product: Core
Classification: Components
Component: DOM (show other bugs)
: unspecified
: x86 Mac OS X
: -- normal (vote)
: mozilla19
Assigned To: Nobody; OK to take it and work on it
:
Mentors:
http://www.ro.me/
Depends on: 795186
Blocks:
  Show dependency treegraph
 
Reported: 2012-10-11 12:12 PDT by Gregor Wagner [:gwagner]
Modified: 2012-10-27 13:17 PDT (History)
5 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
unaffected
fixed


Attachments

Description Gregor Wagner [:gwagner] 2012-10-11 12:12:20 PDT
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] (vacation Aug 25-28) 2012-10-11 12:14:44 PDT
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] 2012-10-11 12:17:58 PDT
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] 2012-10-11 12:18:34 PDT
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] 2012-10-11 12:22:37 PDT
Hm maybe I just changed to another URL. Let me try again.
Comment 5 Gregor Wagner [:gwagner] 2012-10-11 12:34:15 PDT
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] 2012-10-11 12:38:45 PDT
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] 2012-10-11 12:39:26 PDT
But as you can see it is very effective, making CCs around 54 times faster. ;)
Comment 8 Olli Pettay [:smaug] (vacation Aug 25-28) 2012-10-19 03:18:55 PDT
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] 2012-10-19 06:33:27 PDT
Oh, good point.
Comment 10 Benoit Jacob [:bjacob] (mostly away) 2012-10-23 09:26:45 PDT
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.

Note You need to log in before you can comment on or make changes to this bug.