Closed Bug 1068123 Opened 11 years ago Closed 11 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+
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: 11 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: