Closed Bug 1202462 Opened 9 years ago Closed 6 years ago

Octane score gains considerably with incremental GC disabled

Categories

(Core :: JavaScript: GC, defect)

43 Branch
x86_64
Linux
defect
Not set
normal

Tracking

()

RESOLVED WONTFIX

People

(Reporter: tenisthenewnine, Unassigned)

References

Details

So on the latest nightly I get the below Octane scores: With iGC enabled: http://i.imgur.com/u4sxv11.png With it disabled and a restart: http://i.imgur.com/CL77GFv.png I can reproduce this again and again. Is this normal?
Component: Untriaged → JavaScript: GC
Flags: needinfo?(wmccloskey)
Product: Firefox → Core
The main difference I can see on a quick compare of images is Raytrace doubles its score with iGC disabled. That seems strange.
Also, Splay Latency score is halved with iGC disabled.
The latency tests getting worse without iGC is expected. After all they test how long the GC pauses are during the run.
Generally speaking, incremental GC trades away throughput to improve latency. That said, the huge drop in score on Raytrace might be worth looking at. Terrence is more focused on GC perf these days than Bill.
Flags: needinfo?(wmccloskey) → needinfo?(terrence)
This should not be hitting any IGC in the shell and indeed, does not reproduce in the shell. I'll check the browser after morning meetings.
I cannot reproduce in the browser either: with: 38251 without: 35061 So, faster with IGC enabled. Looking at the MOZ_GCTIMER=stdout output, we see some GC events near Raytrace. First for the browser: GC(T+33.751s) ================================================================= Invocation Kind: Normal Reason: ALLOC_TRIGGER Incremental: yes Zones Collected: 1 of 4 Compartments Collected: 1 of 124 MinorGCs since last GC: 636 Store Buffer Overflows: 0 MMU 20ms:49.5%; 50ms:79.8% SCC Sweep Total (MaxPause): 3.236ms (3.236ms) HeapSize: 89.645 MiB Chunk Delta (magnitude): +42 (44) Arenas Relocated: 0.000 MiB ---- Totals ---- Total Time: 10.105ms Max Pause: 10.105ms Begin Callback: 0.001ms Mark Discard Code: 0.015ms Relazify Functions: 0.058ms Purge: 0.002ms Mark: 4.528ms Other: 2.789ms Mark Roots: 0.266ms Buffer Gray Roots: 0.068ms Mark Cross Compartment Wrappers: 0.131ms Mark Rooters: 0.007ms Mark Embedding: 0.004ms Mark Compartments: 0.046ms Unmark: 1.473ms Sweep: 5.355ms Mark During Sweeping: 0.016ms Mark Weak: 0.011ms Mark Gray: 0.002ms Mark Gray and Weak: 0.002ms Finalize Start Callback: 0.020ms Sweep Compartments: 1.979ms Sweep Discard Code: 0.013ms Sweep Base Shapes: 0.005ms Sweep Initial Shapes: 0.008ms Sweep Type Objects: 0.275ms Sweep Regexps: 0.001ms Sweep Miscellaneous: 0.035ms Sweep type information: 1.659ms Other: 1.650ms Sweep type tables and compilations: 0.008ms Free type arena: 0.001ms Sweep Object: 2.908ms Sweep String: 0.001ms Sweep Script: 0.040ms Sweep Shape: 0.043ms Sweep JIT code: 0.003ms Finalize End Callback: 0.301ms Deallocate: 0.010ms End Callback: 0.002ms All Minor GCs: 71.697ms Other: 67.407ms Mark Roots: 4.290ms Other: 2.630ms Mark Rooters: 1.660ms Minor GCs to Evict Nursery: 0.111ms Other: 0.104ms Mark Roots: 0.007ms Mark Rooters: 0.002ms And in the shell: GC(T+5.197s) ================================================================= Invocation Kind: Normal Reason: ALLOC_TRIGGER Incremental: yes Zones Collected: 1 of 3 Compartments Collected: 1 of 3 MinorGCs since last GC: 466 Store Buffer Overflows: 0 MMU 20ms:59.2%; 50ms:83.7% SCC Sweep Total (MaxPause): 1.445ms (1.445ms) HeapSize: 82.961 MiB Chunk Delta (magnitude): +0 (78) Arenas Relocated: 0.000 MiB ---- Totals ---- Total Time: 8.153ms Max Pause: 8.153ms Relazify Functions: 0.040ms Purge: 0.007ms Mark: 4.225ms Other: 2.895ms Mark Roots: 0.010ms Mark Cross Compartment Wrappers: 0.001ms Mark Rooters: 0.003ms Unmark: 1.320ms Sweep: 3.818ms Mark During Sweeping: 0.018ms Mark Incoming Black Pointers: 0.001ms Mark Weak: 0.013ms Mark Gray and Weak: 0.004ms Sweep Compartments: 2.636ms Sweep Discard Code: 0.032ms Sweep Cross Compartment Wrappers: 0.001ms Sweep Base Shapes: 0.001ms Sweep Initial Shapes: 0.006ms Sweep Type Objects: 0.263ms Sweep Miscellaneous: 0.078ms Sweep type information: 2.258ms Other: 2.254ms Sweep type tables and compilations: 0.003ms Free type arena: 0.001ms Sweep Object: 1.063ms Sweep String: 0.001ms Sweep Script: 0.030ms Sweep Shape: 0.035ms Sweep JIT code: 0.027ms Deallocate: 0.001ms All Minor GCs: 44.981ms Other: 39.273ms Mark Roots: 5.708ms Other: 5.235ms Mark Rooters: 0.473ms Minor GCs to Evict Nursery: 0.049ms Mark Roots: 0.009ms Mark Rooters: 0.003ms These appear to be materially the same, at least on my hardware. It would be interesting to see what the MOZ_GCTIMER output is like when it's falling over. My guess is that on a 30% slower machine, the GC is running over budget and having to do a second slice. Since the mutator is much slower with barriers enabled, this could substantially slow down whatever test is unlucky enough to have this happen to it. So this seems like is is probably a case where we are trading off throughput for latency and our awful hacks to keep this from showing up too badly on octane are not engaging correctly. :-/
Flags: needinfo?(terrence)
Status: UNCONFIRMED → RESOLVED
Closed: 6 years ago
Resolution: --- → WONTFIX
You need to log in before you can comment on or make changes to this bug.