Status
()
People
(Reporter: terrence, Assigned: terrence)
Tracking
(Blocks 1 bug)
Firefox Tracking Flags
(Not tracked)
Details
Attachments
(1 attachment, 1 obsolete attachment)
|
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.
|
Assignee | |
Comment 1•5 years ago
|
||
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 | |
Comment 2•5 years ago
|
||
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 3•5 years ago
|
||
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+
|
|
Assignee | |
Comment 4•5 years ago
|
||
https://hg.mozilla.org/integration/mozilla-inbound/rev/a53aa43ab5f4
|
||
Comment 6•5 years ago
|
||
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?
|
|
Assignee | |
Comment 7•5 years ago
|
||
And backed out because windows is missing snprintf. https://hg.mozilla.org/integration/mozilla-inbound/rev/6dc8272079e6
|
|
Assignee | |
Comment 8•5 years ago
|
||
(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.
|
|
Assignee | |
Comment 9•5 years ago
|
||
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.
|
|
Assignee | |
Comment 10•5 years ago
|
||
Not sure why this didn't get closed automatically. In any case, it's in.
Status: ASSIGNED → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → FIXED
You need to log in
before you can comment on or make changes to this bug.
Description
•