Extremely frequent minor GCs and resulting CCs even when idle on simple pages

NEW
Unassigned

Status

()

Core
JavaScript: GC
P3
normal
a year ago
3 months ago

People

(Reporter: kael, Unassigned)

Tracking

({triage-deferred})

50 Branch
triage-deferred
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

(Reporter)

Description

a year ago
My Firefox session experiences extremely frequent minor GCs and CCs at all times. If I have enough tabs open, or a single intensive tab like Twitter, my browser turns into a non-stop jankfest where I see pauses as long as 250ms or more while scrolling or interacting with UI.

I aggressively reduced my profile and configuration to try and nail down a cause for this, but there appears to be no single obvious cause. I also went through the history of builds with mozregression and it seems like this has been going on for a while, to some degree.

Essentially, if I set a tracepoint on StoreBuffer:setAboutToOverflow, even on very simple pages I see it being invoked multiple times a second. Even just scrolling through a simple HTML page with all addons disabled is enough to trigger many minor GCs and resulting CCs. Spinning the mouse cursor in circles on a test page is also sufficient to trigger many minor GCs.

e10s hides a lot of this jank, but that has its own problems (i.e. bug 1294700).

Is this expected behavior, for Firefox to be doing GC+CC multiple times a second even when idle?

For the following test URL, if I just scroll through it with the mousewheel I see 1-2 setAboutToOverflow invocations per second, and those result in GC+CC if I profile using the performance tools. The collections are short (usually) but if I have many tabs open they won't be short anymore.

This seems like it could be the root of most of my performance issues with Firefox over the last year or so: Random inexplicable hitches, seemingly caused by background tabs, or addons, or... nothing. Presumably the hitches are minor GCs that took too long or turned into full GCs, but the performance profiling tools do nothing to help me understand what *caused* the GCs.
Would be good to get to the bottom of this.
Flags: needinfo?(terrence)
(Reporter)

Comment 2

a year ago
I've been running Release channel for a few days now with the same profile (no Twitter though) and everything feels fine. On the other hand, I still see really frequent GCs and cycle reductions/collections at idle or while scrolling in bugzilla. Maybe from having gmail open? My guess is maybe the impact of the GCs and CCs is somehow worse in Aurora right now, even though they show as very fast in the profiler?
If you set javascript.options.mem.log to true, and go to the browser console (filter on "c(" to only see CC/GC entries) what are you seeing when it is janky? That will give more detailed information about GC and CC times.
Also, since you say you're seeing frequent minor GCs, if you set `JS_GC_PROFILE_NURSERY=1000` in your environment, if will print minor GC stats to stderr for every minor GC that takes at least 1000 microsecond. Those logs would be very useful for helping diagnose what is going on.
(Reporter)

Comment 5

a year ago
(In reply to Andrew McCreight [:mccr8] from comment #3)
> If you set javascript.options.mem.log to true, and go to the browser console
> (filter on "c(" to only see CC/GC entries) what are you seeing when it is
> janky? That will give more detailed information about GC and CC times.

Pasting ~100 lines of browser console logs from Aurora with options.mem.log on for about 30 minutes (with Twitter in a background tab). At this point it's janking really bad and the text field here on Bugzilla repaints at about 0.5 frames/second. Interestingly just scrolling the textbox leaves huge white gaps as repainting the text falls behind the compositor. Back to the release channel...

(In reply to Nick Fitzgerald [:fitzgen] [⏰PDT; UTC-7] from comment #4)
> Also, since you say you're seeing frequent minor GCs, if you set
> `JS_GC_PROFILE_NURSERY=1000` in your environment, if will print minor GC
> stats to stderr for every minor GC that takes at least 1000 microsecond.
> Those logs would be very useful for helping diagnose what is going on.

How do I capture the stderr on windows? 2> log.txt? Normally I don't see a console for FF.



------------
GC(T+1085.7)[default] Summary - Max Pause: 40.001ms; MMU 20ms: 0.0%; MMU 50ms: 20.0%; Total: 89.984ms; Zones: 11 of 11 (-0); Compartments: 379 of 379 (-0); HeapSize: 57.207 MiB; HeapChange (abs): +0 (0); 
CC(T+1087.5)[default] max pause: 24ms, total time: 25ms, slices: 2, suspected: 365, visited: 462 RCed and 1373 GCed, collected: 9 RCed and 96 GCed (96|0|0 waiting for GC)
ForgetSkippable 24 times before CC, min: 0 ms, max: 3 ms, avg: 0 ms, total: 8 ms, max sync: 0 ms, removed: 3183
CC(T+1111.1)[default] max pause: 1ms, total time: 2ms, slices: 2, suspected: 436, visited: 855 RCed and 1269 GCed, collected: 24 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 92 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 9 ms, max sync: 0 ms, removed: 15604
CC(T+1140.6)[default] max pause: 1ms, total time: 2ms, slices: 2, suspected: 528, visited: 997 RCed and 1264 GCed, collected: 41 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 115 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 13 ms, max sync: 0 ms, removed: 22128
CC(T+1144.6)[content] max pause: 44ms, total time: 46ms, slices: 2, suspected: 321, visited: 1008 RCed and 2287 GCed, collected: 4 RCed and 0 GCed (104|0|0 waiting for GC)
ForgetSkippable 102 times before CC, min: 0 ms, max: 2 ms, avg: 0 ms, total: 68 ms, max sync: 0 ms, removed: 15993
CC(T+1164.2)[default] max pause: 29ms, total time: 30ms, slices: 2, suspected: 331, visited: 673 RCed and 1263 GCed, collected: 26 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 92 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 9 ms, max sync: 0 ms, removed: 17416
CC(T+1181.9)[default] max pause: 1ms, total time: 2ms, slices: 3, suspected: 561, visited: 1002 RCed and 1262 GCed, collected: 20 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 69 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 6 ms, max sync: 0 ms, removed: 13569
CC(T+1181.7)[content] max pause: 3ms, total time: 5ms, slices: 2, suspected: 242, visited: 766 RCed and 2287 GCed, collected: 80 RCed and 0 GCed (104|0|0 waiting for GC)
ForgetSkippable 56 times before CC, min: 0 ms, max: 2 ms, avg: 0 ms, total: 36 ms, max sync: 0 ms, removed: 13711
CC(T+1200.0)[default] max pause: 1ms, total time: 2ms, slices: 2, suspected: 786, visited: 1879 RCed and 1259 GCed, collected: 48 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 69 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 5 ms, max sync: 0 ms, removed: 13372
CC(T+1200.0)[content] max pause: 2ms, total time: 4ms, slices: 2, suspected: 458, visited: 1395 RCed and 1584 GCed, collected: 20 RCed and 0 GCed (104|0|0 waiting for GC)
ForgetSkippable 28 times before CC, min: 0 ms, max: 2 ms, avg: 0 ms, total: 14 ms, max sync: 0 ms, removed: 9047
GC Slice 0 - Pause: 25.626ms of 10ms budget (@ 0.000ms); Reason: CC_WAITING; Reset: no; Times: Mark Discard Code: 4.397ms, Relazify Functions: 5.341ms, Purge: 4.469ms, Mark: 10.425ms, Mark Roots: 4.539ms, Buffer Gray Roots: 2.423ms, Mark Runtime-wide Data: 1.428ms, Mark Embedding: 0.160ms, Mark Compartments: 0.444ms, Unmark: 5.815ms, Minor GCs to Evict Nursery: 0.300ms, Other: 0.218ms
GC Slice 1 - Pause: 40.047ms of 40ms budget (@ 126.271ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 33.832ms, Minor GCs to Evict Nursery: 6.197ms, Other: 6.136ms
GC Slice 2 - Pause: 40.011ms of 40ms budget (@ 267.076ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 39.969ms
GC Slice 3 - Pause: 40.065ms of 40ms budget (@ 407.564ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 39.836ms, Minor GCs to Evict Nursery: 0.216ms, Other: 0.157ms
GC Slice 4 - Pause: 54.878ms of 40ms budget (@ 547.636ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 24.858ms, Other: 24.855ms, Sweep: 29.566ms, Other: 1.197ms, Mark During Sweeping: 15.254ms, Mark Weak: 4.243ms, Mark Gray: 7.288ms, Mark Gray and Weak: 3.695ms, Finalize Start Callbacks: 0.502ms, Per-Slice Weak Callback: 0.323ms, Per-Compartment Weak Callback: 0.174ms, Sweep Compartments: 9.327ms, Sweep Discard Code: 0.465ms, Sweep Cross Compartment Wrappers: 0.704ms, Sweep Type Objects: 0.447ms, Sweep Breakpoints: 1.740ms, Sweep Regexps: 0.329ms, Sweep Miscellaneous: 14.647ms, Sweep type information: 0.669ms, Other: 0.664ms, Sweep Object: 3.131ms, Sweep Shape: 0.105ms
GC Slice 5 - Pause: 43.209ms of 40ms budget (@ 702.629ms); Reason: INTER_SLICE_GC; Reset: no; Times: Sweep: 43.168ms, Other: 6.843ms, Sweep Atoms: 5.390ms, Sweep Compartments: 23.668ms, Other: 0.156ms, Sweep Miscellaneous: 0.117ms, Sweep type information: 23.364ms, Other: 23.349ms, Sweep String: 1.278ms, Sweep Script: 0.711ms, Sweep Shape: 2.468ms, Sweep JIT code: 0.424ms, Finalize End Callback: 1.096ms, Deallocate: 1.166ms
GC Slice 6 - Pause: 0.264ms of 10ms budget (@ 775.414ms); Reason: REFRESH_FRAME; Reset: no; Times: Minor GCs to Evict Nursery: 0.181ms, Other: 0.130ms
GC(T+1204.8)[content] Summary - Max Pause: 54.878ms; MMU 20ms: 0.0%; MMU 50ms: 0.0%; Total: 244.475ms; Zones: 12 of 12 (-0); Compartments: 229 of 229 (-0); HeapSize: 132.074 MiB; HeapChange (abs): +0 (0); 
CC(T+1206.0)[default] max pause: 1ms, total time: 2ms, slices: 2, suspected: 680, visited: 1130 RCed and 1254 GCed, collected: 81 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 23 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 5 ms, max sync: 0 ms, removed: 7953
CC(T+1206.8)[content] max pause: 45ms, total time: 53ms, slices: 4, suspected: 1872, visited: 7637 RCed and 8335 GCed, collected: 6876 RCed and 6033 GCed (6033|0|0 waiting for GC)
ForgetSkippable 12 times before CC, min: 0 ms, max: 8 ms, avg: 2 ms, total: 28 ms, max sync: 0 ms, removed: 4731
GC Slice 0 - Pause: 10.355ms of 10ms budget (@ 0.000ms); Reason: CC_WAITING; Reset: no; Times: Mark Discard Code: 1.075ms, Relazify Functions: 3.040ms, Purge: 0.252ms, Mark: 5.260ms, Other: 0.688ms, Mark Roots: 2.377ms, Buffer Gray Roots: 1.978ms, Mark Embedding: 0.118ms, Mark Compartments: 0.204ms, Unmark: 2.195ms, Minor GCs to Evict Nursery: 0.353ms, Other: 0.304ms
GC Slice 1 - Pause: 40.002ms of 40ms budget (@ 110.271ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 39.432ms, Minor GCs to Evict Nursery: 0.559ms, Other: 0.517ms
GC Slice 2 - Pause: 40.021ms of 40ms budget (@ 250.885ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 39.849ms, Minor GCs to Evict Nursery: 0.159ms, Other: 0.116ms
GC Slice 3 - Pause: 40.398ms of 40ms budget (@ 390.898ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 18.070ms, Other: 18.033ms, Sweep: 21.840ms, Other: 0.539ms, Mark During Sweeping: 5.249ms, Mark Weak: 0.140ms, Mark Gray: 4.972ms, Mark Gray and Weak: 0.129ms, Finalize Start Callbacks: 0.188ms, Per-Compartment Weak Callback: 0.126ms, Sweep Compartments: 15.465ms, Sweep Discard Code: 0.344ms, Sweep Cross Compartment Wrappers: 0.221ms, Sweep Type Objects: 0.246ms, Sweep Breakpoints: 1.211ms, Sweep Miscellaneous: 4.623ms, Sweep type information: 12.350ms, Other: 12.349ms, Sweep Object: 0.370ms, Minor GCs to Evict Nursery: 0.156ms, Other: 0.113ms
GC Slice 4 - Pause: 4.652ms of 40ms budget (@ 531.584ms); Reason: INTER_SLICE_GC; Reset: no; Times: Sweep: 4.421ms, Other: 0.545ms, Sweep Compartments: 1.255ms, Sweep type information: 1.255ms, Other: 1.254ms, Sweep Script: 0.322ms, Sweep Shape: 1.820ms, Finalize End Callback: 0.388ms, Minor GCs to Evict Nursery: 0.211ms, Other: 0.164ms
CC(T+1212.1)[default] max pause: 1ms, total time: 2ms, slices: 2, suspected: 498, visited: 1312 RCed and 1254 GCed, collected: 9 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 23 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 0 ms, max sync: 0 ms, removed: 4355
GC Slice 5 - Pause: 0.083ms of 40ms budget (@ 636.163ms); Reason: INTER_SLICE_GC; Reset: no; Times: 
GC(T+1211.4)[content] Summary - Max Pause: 40.398ms; MMU 20ms: 0.0%; MMU 50ms: 19.2%; Total: 135.622ms; Zones: 5 of 11 (-0); Compartments: 208 of 226 (-0); HeapSize: 123.383 MiB; HeapChange (abs): +0 (0); 
CC(T+1213.4)[content] max pause: 2ms, total time: 4ms, slices: 2, suspected: 102, visited: 613 RCed and 2308 GCed, collected: 37 RCed and 13 GCed (13|0|0 waiting for GC)
ForgetSkippable 10 times before CC, min: 0 ms, max: 8 ms, avg: 2 ms, total: 22 ms, max sync: 0 ms, removed: 1102
CC(T+1241.9)[default] max pause: 23ms, total time: 24ms, slices: 2, suspected: 408, visited: 874 RCed and 1254 GCed, collected: 12 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 115 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 8 ms, max sync: 0 ms, removed: 18330
CC(T+1260.0)[default] max pause: 1ms, total time: 2ms, slices: 2, suspected: 342, visited: 707 RCed and 1247 GCed, collected: 37 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 69 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 8 ms, max sync: 0 ms, removed: 12832
GC Slice 0 - Pause: 20.630ms of 10ms budget (@ 0.000ms); Reason: FULL_GC_TIMER; Reset: no; Times: Mark Discard Code: 1.895ms, Relazify Functions: 5.426ms, Purge: 3.248ms, Mark: 9.109ms, Mark Roots: 4.200ms, Buffer Gray Roots: 2.329ms, Mark Runtime-wide Data: 1.399ms, Mark Embedding: 0.151ms, Mark Compartments: 0.245ms, Unmark: 4.837ms, Minor GCs to Evict Nursery: 0.387ms, Other: 0.323ms
GC Slice 1 - Pause: 40.069ms of 40ms budget (@ 122.070ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 37.699ms, Minor GCs to Evict Nursery: 2.345ms
GC Slice 2 - Pause: 40.018ms of 40ms budget (@ 262.711ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 39.960ms
GC Slice 3 - Pause: 40.059ms of 40ms budget (@ 402.770ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 40.013ms
GC Slice 4 - Pause: 41.770ms of 40ms budget (@ 543.471ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 26.472ms, Other: 26.449ms, Sweep: 14.603ms, Other: 1.076ms, Mark During Sweeping: 7.704ms, Mark Weak: 0.518ms, Mark Gray: 6.722ms, Mark Gray and Weak: 0.448ms, Finalize Start Callbacks: 0.312ms, Per-Slice Weak Callback: 0.125ms, Per-Compartment Weak Callback: 0.186ms, Sweep Compartments: 4.690ms, Sweep Discard Code: 0.519ms, Sweep Cross Compartment Wrappers: 0.467ms, Sweep Type Objects: 0.530ms, Sweep Breakpoints: 1.600ms, Sweep Miscellaneous: 6.097ms, Sweep type information: 0.620ms, Other: 0.617ms, Sweep Object: 0.714ms, Minor GCs to Evict Nursery: 0.266ms, Other: 0.196ms
GC Slice 5 - Pause: 31.631ms of 40ms budget (@ 685.721ms); Reason: INTER_SLICE_GC; Reset: no; Times: Sweep: 31.193ms, Other: 1.700ms, Sweep Atoms: 7.245ms, Sweep Compartments: 18.493ms, Sweep type information: 18.304ms, Other: 18.287ms, Sweep String: 0.267ms, Sweep Script: 0.449ms, Sweep Shape: 2.020ms, Finalize End Callback: 0.307ms, Deallocate: 0.488ms, Minor GCs to Evict Nursery: 0.417ms, Other: 0.339ms
GC Slice 6 - Pause: 0.324ms of 40ms budget (@ 817.843ms); Reason: INTER_SLICE_GC; Reset: no; Times: Minor GCs to Evict Nursery: 0.252ms, Other: 0.179ms
GC(T+1272.4)[content] Summary - Max Pause: 41.770ms; MMU 20ms: 0.0%; MMU 50ms: 16.5%; Total: 214.751ms; Zones: 11 of 11 (-0); Compartments: 225 of 225 (-0); HeapSize: 123.680 MiB; HeapChange (abs): +0 (0); 
CC(T+1274.2)[content] max pause: 43ms, total time: 44ms, slices: 2, suspected: 267, visited: 1108 RCed and 2307 GCed, collected: 249 RCed and 4 GCed (4|0|0 waiting for GC)
ForgetSkippable 79 times before CC, min: 0 ms, max: 7 ms, avg: 0 ms, total: 69 ms, max sync: 0 ms, removed: 9308
CC(T+1289.4)[default] max pause: 1ms, total time: 2ms, slices: 2, suspected: 453, visited: 970 RCed and 1247 GCed, collected: 18 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 115 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 9 ms, max sync: 0 ms, removed: 18750
CC(T+1313.2)[default] max pause: 25ms, total time: 26ms, slices: 2, suspected: 511, visited: 932 RCed and 1247 GCed, collected: 30 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 92 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 5 ms, max sync: 0 ms, removed: 16638
CC(T+1323.9)[content] max pause: 2ms, total time: 4ms, slices: 2, suspected: 215, visited: 775 RCed and 2298 GCed, collected: 0 RCed and 0 GCed (4|0|0 waiting for GC)
ForgetSkippable 70 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 44 ms, max sync: 0 ms, removed: 8458
CC(T+1330.9)[default] max pause: 2ms, total time: 3ms, slices: 2, suspected: 337, visited: 729 RCed and 1247 GCed, collected: 41 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 69 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 11 ms, max sync: 0 ms, removed: 13195
CC(T+1337.0)[default] max pause: 1ms, total time: 2ms, slices: 2, suspected: 472, visited: 974 RCed and 1247 GCed, collected: 23 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 23 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 2 ms, max sync: 0 ms, removed: 5887
CC(T+1360.8)[default] max pause: 2ms, total time: 3ms, slices: 2, suspected: 414, visited: 905 RCed and 1247 GCed, collected: 27 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 92 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 7 ms, max sync: 0 ms, removed: 15495
CC(T+1360.9)[content] max pause: 45ms, total time: 47ms, slices: 2, suspected: 1496, visited: 2987 RCed and 2293 GCed, collected: 84 RCed and 0 GCed (4|0|0 waiting for GC)
ForgetSkippable 58 times before CC, min: 0 ms, max: 2 ms, avg: 0 ms, total: 41 ms, max sync: 0 ms, removed: 22129
no element foundrequest:1:1
CC(T+1378.5)[default] max pause: 23ms, total time: 24ms, slices: 2, suspected: 640, visited: 1182 RCed and 1247 GCed, collected: 34 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 69 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 3 ms, max sync: 0 ms, removed: 13029
CC(T+1397.5)[content] max pause: 2ms, total time: 4ms, slices: 2, suspected: 255, visited: 1045 RCed and 2291 GCed, collected: 0 RCed and 0 GCed (4|0|0 waiting for GC)
ForgetSkippable 53 times before CC, min: 0 ms, max: 2 ms, avg: 0 ms, total: 32 ms, max sync: 0 ms, removed: 11815
CC(T+1408.1)[default] max pause: 1ms, total time: 2ms, slices: 3, suspected: 588, visited: 1189 RCed and 1247 GCed, collected: 17 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 115 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 5 ms, max sync: 0 ms, removed: 19966
CC(T+1437.9)[default] max pause: 2ms, total time: 3ms, slices: 2, suspected: 563, visited: 1164 RCed and 1232 GCed, collected: 22 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 115 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 4 ms, max sync: 0 ms, removed: 18957
CC(T+1467.6)[default] max pause: 24ms, total time: 25ms, slices: 2, suspected: 432, visited: 1140 RCed and 1232 GCed, collected: 13 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 115 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 6 ms, max sync: 0 ms, removed: 18409
CC(T+1473.6)[default] max pause: 2ms, total time: 3ms, slices: 2, suspected: 354, visited: 923 RCed and 1220 GCed, collected: 10 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 23 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 1 ms, max sync: 0 ms, removed: 4800
CC(T+1494.5)[content] max pause: 47ms, total time: 48ms, slices: 2, suspected: 273, visited: 771 RCed and 2287 GCed, collected: 0 RCed and 0 GCed (4|0|0 waiting for GC)
ForgetSkippable 129 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 74 ms, max sync: 0 ms, removed: 16305
CC(T+1497.6)[default] max pause: 2ms, total time: 3ms, slices: 2, suspected: 423, visited: 1126 RCed and 1220 GCed, collected: 41 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 92 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 4 ms, max sync: 0 ms, removed: 15369
CC(T+1527.3)[default] max pause: 2ms, total time: 4ms, slices: 2, suspected: 457, visited: 1186 RCed and 1220 GCed, collected: 17 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 115 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 3 ms, max sync: 0 ms, removed: 17925
CC(T+1545.3)[default] max pause: 24ms, total time: 25ms, slices: 2, suspected: 377, visited: 1037 RCed and 1220 GCed, collected: 22 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 69 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 7 ms, max sync: 0 ms, removed: 11830
CC(T+1550.2)[content] max pause: 4ms, total time: 6ms, slices: 2, suspected: 2209, visited: 2007 RCed and 2279 GCed, collected: 491 RCed and 0 GCed (4|0|0 waiting for GC)
ForgetSkippable 71 times before CC, min: 0 ms, max: 6 ms, avg: 0 ms, total: 55 ms, max sync: 0 ms, removed: 93498
CC(T+1551.6)[default] max pause: 2ms, total time: 3ms, slices: 2, suspected: 1407, visited: 2943 RCed and 1220 GCed, collected: 34 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 23 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 2 ms, max sync: 0 ms, removed: 8079
GC Slice 0 - Pause: 28.720ms of 10ms budget (@ 0.000ms); Reason: CC_WAITING; Reset: no; Times: Mark Discard Code: 3.181ms, Relazify Functions: 7.572ms, Purge: 4.815ms, Mark: 11.706ms, Mark Roots: 4.446ms, Buffer Gray Roots: 2.368ms, Mark Runtime-wide Data: 1.407ms, Mark Embedding: 0.156ms, Mark Compartments: 0.433ms, Unmark: 7.188ms, Minor GCs to Evict Nursery: 0.725ms, Other: 0.649ms
GC Slice 1 - Pause: 40.039ms of 40ms budget (@ 129.011ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 32.955ms, Minor GCs to Evict Nursery: 7.060ms
GC Slice 2 - Pause: 40.074ms of 40ms budget (@ 269.063ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 40.012ms
GC Slice 3 - Pause: 40.028ms of 40ms budget (@ 409.147ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 39.810ms, Minor GCs to Evict Nursery: 0.203ms, Other: 0.146ms
GC Slice 4 - Pause: 43.156ms of 40ms budget (@ 549.852ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 23.589ms, Other: 23.587ms, Sweep: 19.294ms, Other: 0.822ms, Mark During Sweeping: 11.519ms, Mark Weak: 6.140ms, Mark Gray and Weak: 5.357ms, Finalize Start Callbacks: 0.401ms, Per-Slice Weak Callback: 0.384ms, Sweep Compartments: 6.474ms, Sweep Miscellaneous: 6.384ms, Minor GCs to Evict Nursery: 0.236ms, Other: 0.167ms
GC Slice 5 - Pause: 40.598ms of 40ms budget (@ 693.691ms); Reason: INTER_SLICE_GC; Reset: no; Times: Sweep: 39.817ms, Other: 0.611ms, Mark During Sweeping: 13.474ms, Other: 0.119ms, Mark Weak: 2.466ms, Mark Gray: 8.676ms, Mark Gray and Weak: 2.198ms, Finalize Start Callbacks: 0.357ms, Per-Slice Weak Callback: 0.172ms, Per-Compartment Weak Callback: 0.184ms, Sweep Compartments: 20.174ms, Sweep Discard Code: 0.504ms, Sweep Cross Compartment Wrappers: 0.862ms, Sweep Type Objects: 0.651ms, Sweep Breakpoints: 1.768ms, Sweep Regexps: 0.594ms, Sweep Miscellaneous: 9.936ms, Sweep type information: 12.834ms, Other: 12.822ms, Sweep Object: 5.073ms, Minor GCs to Evict Nursery: 0.304ms, Other: 0.224ms
GC Slice 6 - Pause: 24.977ms of 40ms budget (@ 835.251ms); Reason: INTER_SLICE_GC; Reset: no; Times: Sweep: 24.690ms, Other: 5.295ms, Sweep Atoms: 4.731ms, Sweep Compartments: 7.543ms, Sweep type information: 7.475ms, Other: 7.467ms, Sweep String: 1.907ms, Sweep Script: 0.650ms, Sweep Shape: 2.320ms, Sweep JIT code: 0.310ms, Finalize End Callback: 0.614ms, Deallocate: 1.202ms, Minor GCs to Evict Nursery: 0.268ms, Other: 0.205ms
GC Slice 7 - Pause: 0.234ms of 40ms budget (@ 960.532ms); Reason: INTER_SLICE_GC; Reset: no; Times: Sweep: 0.168ms, Deallocate: 0.168ms
GC(T+1555.3)[content] Summary - Max Pause: 43.156ms; MMU 20ms: 0.0%; MMU 50ms: 13.7%; Total: 258.230ms; Zones: 11 of 11 (-0); Compartments: 228 of 228 (-0); HeapSize: 136.773 MiB; HeapChange (abs): +0 (0); 
CC(T+1557.4)[content] max pause: 47ms, total time: 91ms, slices: 9, suspected: 1359, visited: 40129 RCed and 14348 GCed, collected: 39459 RCed and 12023 GCed (12023|0|0 waiting for GC)
ForgetSkippable 12 times before CC, min: 0 ms, max: 10 ms, avg: 3 ms, total: 36 ms, max sync: 0 ms, removed: 13503
GC Slice 0 - Pause: 12.889ms of 10ms budget (@ 0.000ms); Reason: CC_WAITING; Reset: no; Times: Mark Discard Code: 1.356ms, Relazify Functions: 3.699ms, Purge: 1.604ms, Mark: 5.437ms, Mark Roots: 2.658ms, Buffer Gray Roots: 2.195ms, Mark Embedding: 0.141ms, Mark Compartments: 0.225ms, Unmark: 2.703ms, Minor GCs to Evict Nursery: 0.368ms, Other: 0.315ms
GC Slice 1 - Pause: 40.036ms of 40ms budget (@ 112.992ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 39.354ms, Minor GCs to Evict Nursery: 0.662ms
GC Slice 2 - Pause: 40.034ms of 40ms budget (@ 253.043ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 39.982ms
GC Slice 3 - Pause: 50.291ms of 40ms budget (@ 393.248ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 39.149ms, Other: 39.141ms, Sweep: 10.593ms, Other: 0.609ms, Mark During Sweeping: 6.099ms, Mark Weak: 0.150ms, Mark Gray: 5.791ms, Mark Gray and Weak: 0.152ms, Finalize Start Callbacks: 0.198ms, Per-Compartment Weak Callback: 0.154ms, Sweep Compartments: 3.212ms, Sweep Discard Code: 0.394ms, Sweep Cross Compartment Wrappers: 0.379ms, Sweep Type Objects: 0.422ms, Sweep Breakpoints: 1.358ms, Sweep Miscellaneous: 4.717ms, Sweep Object: 0.470ms, Minor GCs to Evict Nursery: 0.315ms, Other: 0.240ms
GC Slice 4 - Pause: 20.119ms of 40ms budget (@ 543.473ms); Reason: INTER_SLICE_GC; Reset: no; Times: Sweep: 19.881ms, Other: 1.417ms, Sweep Compartments: 15.684ms, Sweep type information: 15.684ms, Other: 15.679ms, Sweep Script: 0.438ms, Sweep Shape: 1.781ms, Finalize End Callback: 0.430ms, Minor GCs to Evict Nursery: 0.216ms, Other: 0.136ms
GC Slice 5 - Pause: 0.333ms of 40ms budget (@ 663.514ms); Reason: INTER_SLICE_GC; Reset: no; Times: Minor GCs to Evict Nursery: 0.258ms, Other: 0.189ms
GC(T+1561.9)[content] Summary - Max Pause: 50.291ms; MMU 20ms: 0.0%; MMU 50ms: 0.0%; Total: 164.015ms; Zones: 5 of 11 (-0); Compartments: 207 of 225 (-0); HeapSize: 124.277 MiB; HeapChange (abs): +0 (0); 
CC(T+1563.9)[content] max pause: 2ms, total time: 4ms, slices: 2, suspected: 169, visited: 712 RCed and 2345 GCed, collected: 84 RCed and 18 GCed (18|0|0 waiting for GC)
ForgetSkippable 12 times before CC, min: 0 ms, max: 7 ms, avg: 2 ms, total: 25 ms, max sync: 0 ms, removed: 1005
CC(T+1575.3)[default] max pause: 2ms, total time: 4ms, slices: 2, suspected: 2804, visited: 4366 RCed and 1205 GCed, collected: 244 RCed and 0 GCed (96|0|0 waiting for GC)
ForgetSkippable 91 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 16 ms, max sync: 0 ms, removed: 20068
GC Slice 0 - Pause: 10.733ms of 10ms budget (@ 0.000ms); Reason: EAGER_ALLOC_TRIGGER; Reset: no; Times: Mark Discard Code: 1.396ms, Relazify Functions: 1.626ms, Purge: 0.284ms, Mark: 6.392ms, Other: 2.497ms, Mark Roots: 2.863ms, Buffer Gray Roots: 1.268ms, Mark Cross Compartment Wrappers: 0.292ms, Mark Compartments: 1.121ms, Unmark: 1.032ms, Minor GCs to Evict Nursery: 0.297ms, Other: 0.208ms
GC Slice 1 - Pause: 10.013ms of 10ms budget (@ 118.459ms); Reason: ALLOC_TRIGGER; Reset: no; Times: Mark: 9.652ms, Minor GCs to Evict Nursery: 0.352ms, Other: 0.247ms, Mark Roots: 0.105ms
GC Slice 2 - Pause: 48.410ms of 40ms budget (@ 291.708ms); Reason: INTER_SLICE_GC; Reset: no; Times: Mark: 27.947ms, Other: 27.495ms, Mark Delayed: 0.452ms, Sweep: 19.809ms, Other: 1.879ms, Mark During Sweeping: 2.396ms, Mark Weak: 0.264ms, Mark Gray: 2.006ms, Mark Gray and Weak: 0.116ms, Finalize Start Callbacks: 0.258ms, Per-Compartment Weak Callback: 0.207ms, Sweep Compartments: 5.926ms, Sweep Discard Code: 0.832ms, Sweep Cross Compartment Wrappers: 2.735ms, Sweep Type Objects: 1.061ms, Sweep Breakpoints: 1.840ms, Sweep Regexps: 0.311ms, Sweep Miscellaneous: 14.439ms, Sweep Object: 9.350ms, Minor GCs to Evict Nursery: 0.160ms
GC Slice 3 - Pause: 26.932ms of 40ms budget (@ 440.435ms); Reason: INTER_SLICE_GC; Reset: no; Times: Sweep: 26.766ms, Other: 3.860ms, Sweep Compartments: 7.547ms, Sweep type information: 7.547ms, Other: 7.543ms, Sweep String: 0.354ms, Sweep Script: 0.407ms, Sweep Shape: 1.432ms, Sweep JIT code: 0.227ms, Finalize End Callback: 12.938ms, Minor GCs to Evict Nursery: 0.155ms, Mark Roots: 0.104ms
GC Slice 4 - Pause: 0.246ms of 40ms budget (@ 567.544ms); Reason: INTER_SLICE_GC; Reset: no; Times: Minor GCs to Evict Nursery: 0.219ms, Other: 0.118ms, Mark Roots: 0.101ms
GC(T+1576.0)[default] Summary - Max Pause: 48.410ms; MMU 20ms: 0.0%; MMU 50ms: 3.2%; Total: 96.511ms; Zones: 1 of 37 (-0); Compartments: 371 of 418 (-0); HeapSize: 70.754 MiB; HeapChange (abs): +0 (0); 
CC(T+1578.0)[default] max pause: 2ms, total time: 4ms, slices: 3, suspected: 910, visited: 2715 RCed and 2488 GCed, collected: 39 RCed and 918 GCed (918|0|0 waiting for GC)
ForgetSkippable 6 times before CC, min: 0 ms, max: 2 ms, avg: 1 ms, total: 6 ms, max sync: 0 ms, removed: 7596
If you launch Firefox from the console, it looks like redirecting stderr is the same as in *nix: http://stackoverflow.com/questions/482678/how-to-capture-stderr-on-windows-dos
I was not actually able to get firefox.exe to print anything to the console, even --help messages. But if redirection works from cmd.exe, that's great!

Looking through that log fragment we appear to be mostly hitting our target latencys. The longest pause in the GC/CC is 50ms or so: nothing in there that would be causing a 0.5s delay when putting down a keystroke.

That said, our default out-of-the-box GC latency situation is pretty much terrible. Unfortunately, lowering our target latencies can result in catastrophically bad performance under some edge-case workloads. Heck, our current conservative estimates already do that. Really we need to move to a fully concurrent GC to fully get rid of GC pauses.

But that doesn't really address the 0.5 second pauses here. I think the next step would be to collect and upload a cleopatra profile[1] for us to pore over. Hopefully that will show something up. Maybe GC, maybe not, that we can investigate next.

1- https://developer.mozilla.org/en-US/docs/Mozilla/Performance/Profiling_with_the_Built-in_Profiler
Flags: needinfo?(terrence)
(In reply to Terrence Cole [:terrence] from comment #7)
> I was not actually able to get firefox.exe to print anything to the console,
> even --help messages. But if redirection works from cmd.exe, that's great!

I think this is because Gecko's console redirection code tries to set *stdout [1], which silently does nothing as of Visual Studio 2015 (nice one, Microsoft) [2]. Recently ran into that for a pet project. The supported way seems to be to call freopen("CONOUT$", "w", stdout) and the equivalent for stderr. I should confirm and file a bug.

[1] https://dxr.mozilla.org/mozilla-central/rev/6e191a55c3d23e83e6a2e72e4e80c1dc21516493/toolkit/xre/nsNativeAppSupportWin.cpp#392
[2] http://stackoverflow.com/questions/34143430/visual-studio-2015-issues-with-an-attached-console-i-o
(Reporter)

Comment 9

a year ago
(In reply to Terrence Cole [:terrence] from comment #7)
> Looking through that log fragment we appear to be mostly hitting our target
> latencys. The longest pause in the GC/CC is 50ms or so: nothing in there
> that would be causing a 0.5s delay when putting down a keystroke.

Does the log describe the interval between pauses? Because interval is part of the problem. The observed delay probably feels longer in part due to the e10s+compositor issues (in another bug I mentioned that disabling e10s eliminates some forms of jank). In some profiles I see dozens of pauses in a short span of time.

> But that doesn't really address the 0.5 second pauses here. I think the next
> step would be to collect and upload a cleopatra profile[1] for us to pore
> over. Hopefully that will show something up. Maybe GC, maybe not, that we
> can investigate next.

Cleopatra is currently pretty broken for profiling this case; I filed a bug about it. My cleopatra reports were also considered suspect since they don't seem to actually show the pauses or workload. Not sure what to do there.
Keywords: triage-deferred
Priority: -- → P3
You need to log in before you can comment on or make changes to this bug.