1202462 - Octane score gains considerably with incremental GC disabled

Status: RESOLVED WONTFIX

(Core :: JavaScript: GC, defect)

Description

[Grant]

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?

Comment 1

[Hugh Nougher [:Hughman]]

The main difference I can see on a quick compare of images is Raytrace doubles its score with iGC disabled. That seems strange.

Comment 2

[Mayank Bansal]

Also, Splay Latency score is halved with iGC disabled.

Comment 3

[Hugh Nougher [:Hughman]]

The latency tests getting worse without iGC is expected.
After all they test how long the GC pauses are during the run.

Comment 4

[Andrew McCreight [:mccr8]]

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.

Comment 5

[Terrence Cole [: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.

Comment 6

[Terrence Cole [:terrence]]

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. :-/