1101111 - CC and GC running when scrolling pages not when idle

Status: RESOLVED INCOMPLETE

(Core :: JavaScript: GC, defect)

Description

[Chris]

This affects both v31 ESR and Release v33.1.1

I observed on v33.x lots of stutters when scrolling pages, some pages its very evident others not so evident but still noticeble.  I then started to debug the issue.

I enabled javascript.options.mem.log;false, set the browser to left side of screen, and open the browser console on right side of screen.

I observed when scrolling a page a CC appears approx once every 1-2 seconds, a GC then also appears either every 7 seconds or every 14-15 seconds, with the reason CC_WAITING, when thie GC runs, the stutter occurs.  If I leave the browser idle, usually CC run infrequently and no GC at all.  This to me seems backwards, GC should be suspended when is interactive use and only run when idle.  Also typing in form boxes will trigger the frequent CC and GC as well.

For some reason the GC pauses are way worse in release 33 they run with the same pattern and the log even reports the same duration but the stutters are way worse, which is why I didnt notice on ESR so much.  I am aware there has been some GC changes which are supposed to be performance improvements between v31 and v33, maybe these have occidentally caused a regression?

I also tried toggling incremental GC, with it off the stutters are more like a quick pause so the effect of GC is shorter but also it completely pauses scrolling for a short period, with incremental enabled the scrolling isnt paused but it stutters instead and for longer.

The reason GC is probably affecting me is I have a lot of background tabs in my sessions was 540, I have now reduced my session to 180 tabs, and this has decreased the GC duration and also reduced the stutter effect, but th stutter is still there, I think the clear problem here is that for whatever reason firefox is choosing to run GC and CC whilst I am using my mouse, which is counter productive.

An obvious issue which I hope is fixed in future development of firefox is also that everything shares 1 process, it seems the OMTC for graphics has no effect on this problem.

I have a powerful rig, haswell 4670k overclocked to 4.3ghz, 16 gig of ram, samsung 850 pro ssd, this simply shouldnt be happening.

Comment 1

[Chris]

an additional comment, the stutter still occurs in safe mode.

Comment 2

[Andrew McCreight [:mccr8]]

What does the information in the GC and CC log with the javascript.options.mem.log option set look like?  Just paste one or two typical looking ones, please.

Comment 3

[Andrew McCreight [:mccr8]]

Also, you could try disabling OMTC and see if that helps.  The option is layers.offmainthreadcomposition.enabled, I think.  There was some issue where we accidentally made IGC not work quite properly with OMTC, which I think has been fixed in beta, but not in release yet.

Comment 4

[Andrew McCreight [:mccr8]]

Hmm, though maybe safe mode disabled OMTC.

Comment 5

[Chris]

Hi, sadly I have already tried disabled that and is actually still off now as I forgot I disabled it, the behaviour has also now changed,it has been thrashing GC with the browser idle now as well since I can see all the cpu spikes in my graphs.

I will restart again in safe mode and paste you some lines from the log.

The stuttering has been so bad I disabled smooth scrolling to try and hide the problem.

Comment 6

[Chris]

ok will paste the results, interesting is that when smooth scrolling is disabled only frequent CC's occur but not GCC, when smooth scrolling was turned back on the GCC's also occured, its the GCC's that cause the stutters.  Safe mode vs normal mode both have the problem but it is less severe in safe mode, the time for GC to run is lower and it can be less frequent.  These results are from safe mode.  Iw as thinking about making a new profile, but if I have the problem in safe mode does that suggest a new profile wont fix it?

Also the reason given for GC changes in safe mode vs normal.

GC(T+181.1) Max Pause: 69.8ms, Total Time: 165.8ms, Zones Collected: 229, Total Zones: 229, Total Compartments: 663, Minor GCs: 9, MMU (20ms): 0%, MMU (50ms): 0%, SCC Sweep Total: 26.4ms, SCC Sweep Max Pause: 15.3ms, Allocated: 75MB, +Chunks: 0, -Chunks: 0
    Slice: 0, Pause: 21.2 (When: 0.0ms, Reason: CC_WAITING): Mark Discard Code: 0.2ms, Mark: 19.7ms, Mark Roots: 6.8ms
    Slice: 3, Pause: 69.8 (When: 386.7ms, Reason: INTER_SLICE_GC): Sweep: 69.5ms, Mark During Sweeping: 37.2ms, Mark Weak: 29.0ms, Mark Gray: 6.6ms, Mark Gray and Weak: 1.0ms, Finalize Start Callback: 11.4ms, Sweep Compartments: 16.0ms, Sweep Tables: 12.0ms, Sweep Cross Compartment Wrappers: 2.4ms, Sweep Base Shapes: 2.9ms, Sweep Initial Shapes: 2.1ms, Sweep Type Objects: 1.3ms, Sweep Breakpoints: 0.4ms, Discard Analysis: 2.1ms, Discard TI: 0.5ms, Sweep Types: 1.3ms, Sweep Object: 2.4ms, Sweep String: 0.1ms, Sweep Script: 0.1ms, Sweep Shape: 0.3ms, Sweep JIT code: 0.1ms, Finalize End Callback: 0.1ms
    Slice: 4, Pause: 11.1 (When: 556.7ms, Reason: INTER_SLICE_GC): Sweep: 10.7ms, Mark During Sweeping: 0.2ms, Mark Weak: 0.1ms, Finalize Start Callback: 0.9ms, Sweep Atoms: 1.7ms, Sweep Compartments: 0.3ms, Sweep Tables: 0.2ms, Sweep Base Shapes: 0.1ms, Sweep Object: 0.6ms, Sweep Script: 0.5ms, Sweep Shape: 3.5ms, Finalize End Callback: 2.4ms, Deallocate: 0.3ms
    Totals: Mark Discard Code: 0.2ms, Mark: 42.8ms, Mark Roots: 6.8ms, Sweep: 120.4ms, Mark During Sweeping: 42.5ms, Mark Incoming Black Pointers: 0.2ms, Mark Weak: 31.3ms, Mark Incoming Gray Pointers: 0.2ms, Mark Gray: 6.8ms, Mark Gray and Weak: 2.5ms, Finalize Start Callback: 34.3ms, Sweep Atoms: 1.7ms, Sweep Compartments: 22.0ms, Sweep Discard Code: 0.2ms, Sweep Tables: 15.0ms, Sweep Cross Compartment Wrappers: 2.6ms, Sweep Base Shapes: 3.8ms, Sweep Initial Shapes: 2.5ms, Sweep Type Objects: 1.6ms, Sweep Breakpoints: 0.6ms, Discard Analysis: 3.8ms, Discard TI: 0.6ms, Free TI Arena: 0.2ms, Sweep Types: 2.3ms, Sweep Object: 3.4ms, Sweep String: 0.5ms, Sweep Script: 0.9ms, Sweep Shape: 4.5ms, Sweep JIT code: 0.4ms, Finalize End Callback: 2.7ms, Deallocate: 0.3ms
CC(T+183.1) max pause: 5ms, total time: 5ms, slices: 1, suspected: 484, visited: 2142 RCed and 409 GCed, collected: 1 RCed and 47 GCed (48|326 waiting for GC)
ForgetSkippable 11 times before CC, min: 1 ms, max: 11 ms, avg: 2 ms, total: 24 ms, max sync: 0 ms, removed: 1915
CC(T+189.2) max pause: 5ms, total time: 5ms, slices: 1, suspected: 900, visited: 2851 RCed and 359 GCed, collected: 0 RCed and 0 GCed (48|1348 waiting for GC)
ForgetSkippable 14 times before CC, min: 1 ms, max: 2 ms, avg: 1 ms, total: 15 ms, max sync: 0 ms, removed: 2400
CC(T+195.2) max pause: 5ms, total time: 5ms, slices: 1, suspected: 900, visited: 2839 RCed and 359 GCed, collected: 0 RCed and 0 GCed (48|2368 waiting for GC)
ForgetSkippable 14 times before CC, min: 1 ms, max: 2 ms, avg: 1 ms, total: 15 ms, max sync: 0 ms, removed: 2488
CC(T+201.3) max pause: 5ms, total time: 5ms, slices: 1, suspected: 902, visited: 2846 RCed and 359 GCed, collected: 0 RCed and 0 GCed (48|3393 waiting for GC)
ForgetSkippable 14 times before CC, min: 1 ms, max: 2 ms, avg: 1 ms, total: 16 ms, max sync: 0 ms, removed: 2562
GC(T+205.9) Max Pause: 59.6ms, Total Time: 153.4ms, Zones Collected: 228, Total Zones: 228, Total Compartments: 662, Minor GCs: 7, MMU (20ms): 0%, MMU (50ms): 0%, SCC Sweep Total: 22.4ms, SCC Sweep Max Pause: 12.2ms, Allocated: 75MB, +Chunks: 0, -Chunks: 0
    Slice: 0, Pause: 20.7 (When: 0.0ms, Reason: CC_WAITING): Mark Discard Code: 0.2ms, Mark: 19.9ms, Mark Roots: 6.5ms
    Slice: 3, Pause: 59.6 (When: 385.1ms, Reason: INTER_SLICE_GC): Sweep: 59.3ms, Mark During Sweeping: 34.2ms, Mark Weak: 24.9ms, Mark Gray: 6.2ms, Mark Gray and Weak: 0.8ms, Finalize Start Callback: 8.9ms, Sweep Compartments: 13.9ms, Sweep Tables: 10.3ms, Sweep Cross Compartment Wrappers: 1.6ms, Sweep Base Shapes: 2.4ms, Sweep Initial Shapes: 2.1ms, Sweep Type Objects: 1.1ms, Sweep Breakpoints: 0.4ms, Discard Analysis: 1.9ms, Discard TI: 0.4ms, Sweep Types: 1.3ms, Sweep Object: 0.6ms, Sweep Shape: 0.2ms
    Slice: 4, Pause: 9.7 (When: 545.0ms, Reason: INTER_SLICE_GC): Sweep: 9.4ms, Mark During Sweeping: 0.2ms, Mark Weak: 0.1ms, Finalize Start Callback: 0.9ms, Sweep Atoms: 1.8ms, Sweep Compartments: 0.3ms, Sweep Tables: 0.2ms, Sweep Base Shapes: 0.1ms, Sweep Object: 0.5ms, Sweep Script: 0.5ms, Sweep Shape: 3.1ms, Finalize End Callback: 1.6ms, Deallocate: 0.4ms
    Totals: Mark Discard Code: 0.2ms, Mark: 43.5ms, Mark Roots: 6.5ms, Sweep: 108.1ms, Mark During Sweeping: 39.4ms, Mark Incoming Black Pointers: 0.2ms, Mark Weak: 27.1ms, Mark Incoming Gray Pointers: 0.1ms, Mark Gray: 6.4ms, Mark Gray and Weak: 2.3ms, Finalize Start Callback: 31.1ms, Sweep Atoms: 1.8ms, Sweep Compartments: 20.0ms, Sweep Discard Code: 0.2ms, Sweep Tables: 13.3ms, Sweep Cross Compartment Wrappers: 1.7ms, Sweep Base Shapes: 3.3ms, Sweep Initial Shapes: 2.5ms, Sweep Type Objects: 1.4ms, Sweep Breakpoints: 0.5ms, Discard Analysis: 3.6ms, Discard TI: 0.6ms, Free TI Arena: 0.2ms, Sweep Types: 2.2ms, Sweep Object: 1.4ms, Sweep String: 0.4ms, Sweep Script: 0.9ms, Sweep Shape: 4.0ms, Sweep JIT code: 0.4ms, Finalize End Callback: 1.7ms, Deallocate: 0.4ms

Comment 7

[Chris]

Ok in this test the reason is same as normal CC_WAITING.  Last time I tested on safe mode it was a different reason, but CC_WAITING is what I normally see anyway.

Comment 8

[Chris]

If you are still interested, I dont know as you havent replied.

I made a brand new profile and installed my extensions one by one.

Observations.

1 - With no extensions installed, no customisations made, and just the default firefox page loaded for a new profile, the CC and GC run frequently when scrolling although they dont cause stutters.
2 - With my saved session loaded, and bare bones extensions installed, tabmixplus, session manager, noscript.  The behaviour is the same but with longer run times for the CC and GC, stutters barely noticeble but are there for GC.
3 - After testing all my extensions, I observed loading useragent switcher causes the frequent CC to still occur with the browser idle, without this extension it only occurs when scrolling or using multimedia content.
4 - I have still to test request policy and youtube center.  Speed dial extension seems a bit problematic with causing idle CC's but isnt as bad as user agent switcher.

On the new profile tho things are defenitly improved although the CC and GC is still frequent the stutters are sigificantly improved, I have readded most of my custimisations (not touched GC, javascript settings) is things like disabling OCSP, RC4, disabling trim url's, ram disk for cache but not playing with GC, acceleration etc.

Comment 9

[Wayne Mery (:wsmwk)]

(In reply to Chris from comment #8)
> If you are still interested, I dont know as you havent replied.
> 
> I made a brand new profile and installed my extensions one by one.
> 
> Observations.
> 
> 1 - With no extensions installed, no customisations made, and just the
> default firefox page loaded for a new profile, the CC and GC run frequently
> when scrolling although they dont cause stutters.
> 2 - With my saved session loaded, and bare bones extensions installed,
> tabmixplus, session manager, noscript.  The behaviour is the same but with
> longer run times for the CC and GC, stutters barely noticeble but are there
> for GC.
> 3 - After testing all my extensions, I observed loading useragent switcher
> causes the frequent CC to still occur with the browser idle, without this
> extension it only occurs when scrolling or using multimedia content.
> 4 - I have still to test request policy and youtube center.  Speed dial
> extension seems a bit problematic with causing idle CC's but isnt as bad as
> user agent switcher.
> 
> On the new profile tho things are defenitly improved although the CC and GC
> is still frequent the stutters are sigificantly improved, I have readded
> most of my custimisations (not touched GC, javascript settings) is things
> like disabling OCSP, RC4, disabling trim url's, ram disk for cache but not
> playing with GC, acceleration etc.

is author of  user agent switcher aware of this?
what is your final conclusion?

Comment 11

[Wayne Mery (:wsmwk)]

mccr8, 
Chris seems to be gone. (I PM him in February and no response)
I'm not sure I see anything actionable here. What do you think?