1300826 - GC statistics: sweep misc timing is greater than total

Status: RESOLVED INVALID

(Core :: JavaScript: GC, defect)

Description

[Steve Fink [:sfink] [:s:]]

In the following slice, the GC statistics code is reporting that Sweep took 16.553ms, 7.364ms of that was in Sweep Compartments, and 15.650ms of *that* was in Sweep Miscellaneous.

From looking at the code, it seems like Sweep Miscellaneous all runs on the main thread. So I don't understand how it can be larger than Sweep Compartments.

The relevant phases are PHASE_SWEEP_COMPARTMENTS and PHASE_SWEEP_MISC. The stats could would assert if those were not properly nested, so the compartment sweep phase should record a start timestamp, then one or more misc sweep phases should start and stop, and only then the compartment sweep would record a stop. But then I don't know how the totals could come to what they did.

I'll add an assert to that effect and see if I can reproduce this in a simpler run. (I'm seeing this in a whole-browser test case.)

  ---- Slice 4 ----
    Reason: INTER_SLICE_GC
    Reset: no
    State: Mark -> Sweep
    Page Faults: 0
    Pause: 56.696ms of 40ms budget (@ 683.944ms)
      Wait Background Thread: 0.001ms
      Mark: 37.332ms
        Other: 37.203ms
        Mark Delayed: 0.129ms
      Sweep: 16.553ms
        Other: 0.950ms
        Mark During Sweeping: 4.054ms
          Mark Incoming Black Pointers: 0.001ms
          Mark Weak: 1.235ms
          Mark Incoming Gray Pointers: 0.001ms
          Mark Gray: 1.699ms
          Mark Gray and Weak: 1.116ms
        Finalize Start Callbacks: 0.133ms
          Per-Slice Weak Callback: 0.120ms
          Per-Compartment Weak Callback: 0.011ms
        Sweep Compartments: 7.364ms
          Sweep Discard Code: 1.119ms
          Sweep Cross Compartment Wrappers: 1.457ms
          Sweep Type Objects: 2.361ms
          Sweep Breakpoints: 0.982ms
          Sweep Regexps: 2.511ms
          Sweep Miscellaneous: 15.650ms
          Sweep type information: 0.590ms
            Other: 0.581ms
            Sweep type tables and compilations: 0.009ms
        Sweep Object: 4.049ms
        Sweep Script: 0.001ms
        Sweep Shape: 0.001ms
        Finalize End Callback: 0.001ms
      Minor GCs to Evict Nursery: 2.434ms
        Other: 2.323ms
        Mark Roots: 0.111ms
          Other: 0.080ms
          Mark Rooters: 0.031ms

Comment 1

[Steve Fink [:sfink] [:s:]]

Never mind, I'm an idiot. I was confused because there *is* a portion of PHASE_SWEEP_MISC that is forced to be on the main thread, but other portions happen offthread.

It might be worth splitting out a separate PHASE_SWEEP_MISC_FG or something, but it's not a big deal now that I know what's going on.