Closed Bug 1068123 Opened 6 years ago Closed 6 years ago

Fix gc Statistics logging

Categories

(Core :: JavaScript: GC, defect)

Product:
Core
Component:
JavaScript: GC
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED

People

(Reporter: terrence, Assigned: terrence)

References

(Blocks 1 open bug)

Details

Attachments

(1 file, 1 obsolete file)

send_more_verbose_logs_to_the_gc_log_file-v1.diff
20.19 KB, patch
jonco
: review+
Details | Diff | Splinter Review 
Right now it (1) sometimes misses long slices; (2) is totally unreadable; and (3) does not include entry counts in the table sweeping.
I finished and tested the parallel sweeping infrastructure last night and found myself at a total loss as to what parts of sweeping should actually be done in parallel. Thus, I took today to make our gc logging output more useful. For now, this only changes output going to the MOZ_GCTIMER log, not to the console or json output mechanisms.

I also found out why we dropped that 30ms slice but showed 2 <20ms slices. The reason is that we always show the first and last slice, but ignore slices that are less than 42ms. 42ms seems /way/ too high now, so I've lowered this to 10ms too.

This is a sample of the new output while I was on cnn.com in a fresh profile:

GC(T+50.851s) =================================================================
  Reason: CC_WAITING
  Incremental: yes
  Zones Collected: 8 of 8
  Compartments Collected: 253 of 253
  MinorGCs since last GC: 3
  MMU 20ms:0.000; 50ms:0.582
  SCC Sweep Total (MaxPause): 5.627ms (5.460ms)
  HeapSize: 44.578 MiB
  Chunk Delta (magnitude): +0  (0)
  ---- Slice 0 ----
    Reason: CC_WAITING
    Reset: no
    Page Faults: 0
    Pause: 20.919ms  (@ 0.000ms)
      Begin Callback: 0.001ms
      Mark Discard Code: 0.709ms
      Purge: 0.042ms
      Mark: 19.272ms  (unaccounted: 15.413ms)
        Mark Roots: 3.859ms
  ---- Slice 1 ----
    Reason: INTER_SLICE_GC
    Reset: no
    Page Faults: 0
    Pause: 16.994ms  (@ 120.841ms)
      Mark: 16.804ms  (unaccounted: 16.660ms)
        Mark Delayed: 0.144ms
  ---- Slice 2 ----
    Reason: INTER_SLICE_GC
    Reset: no
    Page Faults: 0
    Pause: 13.226ms  (@ 238.211ms)
      Wait Background Thread: 0.001ms
      Mark: 0.028ms
        Mark Delayed: 0.011ms
      Sweep: 12.308ms
        Mark During Sweeping: 1.461ms
          Mark Incoming Black Pointers: 0.003ms
          Mark Weak: 0.349ms
          Mark Incoming Gray Pointers: 0.002ms
          Mark Gray: 1.077ms
          Mark Gray and Weak: 0.026ms
        Finalize Start Callback: 0.151ms
        Sweep Atoms: 1.938ms
        Sweep Symbol Registry: 0.001ms
        Sweep Compartments: 5.895ms
          Sweep Discard Code: 0.479ms
          Sweep Tables: 2.317ms
            Sweep Cross Compartment Wrappers: 0.228ms
            Sweep Base Shapes: 0.973ms
            Sweep Initial Shapes: 0.576ms
            Sweep Type Objects: 0.206ms
          Discard Analysis: 3.070ms
            Discard TI: 0.850ms
            Sweep Types: 2.215ms
        Sweep Object: 0.216ms
        Sweep String: 0.022ms
        Sweep Script: 0.378ms
        Sweep Shape: 1.072ms
        Sweep JIT code: 0.027ms
        Finalize End Callback: 0.463ms
        Deallocate: 0.431ms
      End Callback: 0.004ms
  ---- Totals ----
    Total Time: 0.000
    Max Pause: 0.000
      Begin Callback: 0.001ms
      Wait Background Thread: 0.001ms
      Mark Discard Code: 0.709ms
      Purge: 0.042ms
      Mark: 36.104ms  (unaccounted: 32.090ms)
        Mark Roots: 3.859ms
        Mark Delayed: 0.155ms
      Sweep: 12.308ms
        Mark During Sweeping: 1.461ms
          Mark Incoming Black Pointers: 0.003ms
          Mark Weak: 0.349ms
          Mark Incoming Gray Pointers: 0.002ms
          Mark Gray: 1.077ms
          Mark Gray and Weak: 0.026ms
        Finalize Start Callback: 0.151ms
        Sweep Atoms: 1.938ms
        Sweep Symbol Registry: 0.001ms
        Sweep Compartments: 5.895ms
          Sweep Discard Code: 0.479ms
          Sweep Tables: 2.317ms
            Sweep Cross Compartment Wrappers: 0.228ms
            Sweep Base Shapes: 0.973ms
            Sweep Initial Shapes: 0.576ms
            Sweep Type Objects: 0.206ms
          Discard Analysis: 3.070ms
            Discard TI: 0.850ms
            Sweep Types: 2.215ms
        Sweep Object: 0.216ms
        Sweep String: 0.022ms
        Sweep Script: 0.378ms
        Sweep Shape: 1.072ms
        Sweep JIT code: 0.027ms
        Finalize End Callback: 0.463ms
        Deallocate: 0.431ms
      End Callback: 0.004ms

GC(T+53.571s) =================================================================
  Reason: DOM_WORKER
  Incremental: no - requested
  Zones Collected: 2 of 2
  Compartments Collected: 2 of 2
  MinorGCs since last GC: 1
  MMU 20ms:0.945; 50ms:0.978
  SCC Sweep Total (MaxPause): 0.067ms (0.067ms)
  HeapSize: 0.441 MiB
  Chunk Delta (magnitude): +0  (0)
  ---- Totals ----
    Total Time: 0.000
    Max Pause: 0.000
      Begin Callback: 0.001ms
      Wait Background Thread: 0.001ms
      Purge: 0.002ms
      Mark: 0.420ms
        Mark Roots: 0.038ms
      Sweep: 0.133ms
        Mark During Sweeping: 0.005ms
          Mark Incoming Black Pointers: 0.001ms
          Mark Gray: 0.004ms
        Sweep Atoms: 0.018ms
        Sweep Compartments: 0.069ms
          Sweep Discard Code: 0.009ms
          Sweep Tables: 0.022ms
            Sweep Cross Compartment Wrappers: 0.001ms
            Sweep Base Shapes: 0.008ms
            Sweep Initial Shapes: 0.006ms
            Sweep Type Objects: 0.004ms
          Discard Analysis: 0.037ms
            Discard TI: 0.014ms
            Free TI Arena: 0.001ms
            Sweep Types: 0.021ms
        Sweep Object: 0.006ms
        Sweep Script: 0.002ms
        Sweep Shape: 0.008ms
        Sweep JIT code: 0.017ms
        Deallocate: 0.004ms
      End Callback: 0.364ms
Assignee: nobody → terrence
Status: NEW → ASSIGNED
Attachment #8491862 - Flags: review?(jcoppeard)
D'oh! I made the unaccounted tracking threshhold much too large. Lowering this to 50us shows us that we're missing about 500us of work under sweep tables that we should add accounting for.
Attachment #8491862 - Attachment is obsolete: true
Attachment #8491862 - Flags: review?(jcoppeard)
Attachment #8491868 - Flags: review?(jcoppeard)
Comment on attachment 8491868 [details] [diff] [review]
send_more_verbose_logs_to_the_gc_log_file-v1.diff

Review of attachment 8491868 [details] [diff] [review]:
-----------------------------------------------------------------

Great, this is much more readable.

I like the idea of reporting unaccounted time too.
Attachment #8491868 - Flags: review?(jcoppeard) → review+
Duplicate of this bug: 1066135
This is really nice.

(In reply to Terrence Cole [:terrence] from comment #1)
>   MMU 20ms:0.000; 50ms:0.582

Could these be reported as percentages? I *think* the second one here is 58.2%.

>       Mark: 19.272ms  (unaccounted: 15.413ms)
>         Mark Roots: 3.859ms

I had to think about what "unaccounted" meant (is it somehow stuff that got missed in the whole thing? Oh, wait, no.) Would it be too messy to make an "Other" subcategory instead and put it all there?

>     Page Faults: 0

What are page faults here?

>     Total Time: 0.000
>     Max Pause: 0.000

In your example, it seemed like these are always zero.

Are you going to split out the table entry counts into a separate bug?
And backed out because windows is missing snprintf.
https://hg.mozilla.org/integration/mozilla-inbound/rev/6dc8272079e6
(In reply to Steve Fink [:sfink] from comment #6)
> This is really nice.
> 
> (In reply to Terrence Cole [:terrence] from comment #1)
> >   MMU 20ms:0.000; 50ms:0.582
> 
> Could these be reported as percentages? I *think* the second one here is
> 58.2%.

Yes, I will do that when I re-land.

> >       Mark: 19.272ms  (unaccounted: 15.413ms)
> >         Mark Roots: 3.859ms
> 
> I had to think about what "unaccounted" meant (is it somehow stuff that got
> missed in the whole thing? Oh, wait, no.) Would it be too messy to make an
> "Other" subcategory instead and put it all there?

Good idea! Will be a bit awkward to do, but maybe not too bad.

> >     Page Faults: 0

Effed if I know.

> What are page faults here?
> 
> >     Total Time: 0.000
> >     Max Pause: 0.000
> 
> In your example, it seemed like these are always zero.

Yup. Forgot to wrap them in t(), so they were getting interpreted as really tiny doubles.

> Are you going to split out the table entry counts into a separate bug?

Yes.
This needed to use JS_snprintf on windows and needed a tweak to the malloc detector.
https://hg.mozilla.org/integration/mozilla-inbound/rev/e76c7a8df029

Builds on all platforms on try:
https://tbpl.mozilla.org/?tree=Try&rev=6944d08a3ffc

Tests were green on the previous push on all platforms where it built.
Not sure why this didn't get closed automatically. In any case, it's in.
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.