Closed Bug 1309651 Opened 4 years ago Closed 3 years ago

Record cpu time spent in GC helper threads

Categories

(Core :: JavaScript: GC, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
mozilla55
Tracking Status
firefox55 --- fixed

People

(Reporter: sfink, Assigned: jonco)

References

Details

Attachments

(1 file, 2 obsolete files)

In bug 1306249, I am removing the recording of time spend in GC helper threads, but it would be good to record this time as well. I'd rather not continue on with the current code, though, so I would want to rewrite the dag into a simple tree before adding in any additional recording.
Assignee: nobody → jcoppeard
Attached patch bug1309651-record-parallel-time (obsolete) — Splinter Review
Add a new stats phase for waiting on parallel tasks and make GCRuntime::joinTask enter this phase while waiting.  

Add Statistics::recordParallelTime to store these times in a second phase time table.  I made this work in the same way as the main thread table, with each phase including the time for its children.  I mainly did this so that existing functions work on either kind of table but it's not strictly required.

Add a telemetry history for slow tasks like the existing slow phase one.  How we detect whether to record this is slightly handwavy: if we're in a slice that's twice over budget and waiting for parallel tasks took at least half of that, then we record the longest task.  This seems OK to me but could probably be improved.
Attachment #8869076 - Flags: review?(sphink)
Comment on attachment 8869076 [details] [diff] [review]
bug1309651-record-parallel-time

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

The only thing I thought of for this was perhaps calling these times "work" instead of the "time". So eg instead of phaseTimes and parallelTimes, it would be phaseTimes and phaseWork. (Or "CPUSeconds" if you don't like "work".)

Up to you, though.

::: js/src/gc/Statistics.cpp
@@ +993,5 @@
>              if (sliceTime.ToMilliseconds() > 2 * budget_ms) {
> +                reportLongestPhase(slice.phaseTimes, JS_TELEMETRY_GC_SLOW_PHASE);
> +                // If we spend a significant length of tiem waiting for parallel
> +                // tasks then report the longest task.
> +                TimeDuration joinTime = SumPhase(PhaseKind::JOIN_PARALLEL_TASKS, slice.phaseTimes);

*time

@@ +995,5 @@
> +                // If we spend a significant length of tiem waiting for parallel
> +                // tasks then report the longest task.
> +                TimeDuration joinTime = SumPhase(PhaseKind::JOIN_PARALLEL_TASKS, slice.phaseTimes);
> +                if (joinTime.ToMilliseconds() > budget_ms)
> +                    reportLongestPhase(slice.parallelTimes, JS_TELEMETRY_GC_SLOW_TASK);

Nice!
Attachment #8869076 - Flags: review?(sphink) → review+
(In reply to Steve Fink [:sfink] [:s:] from comment #2)
> The only thing I thought of for this was perhaps calling these times "work"
> instead of the "time". So eg instead of phaseTimes and parallelTimes, it
> would be phaseTimes and phaseWork. (Or "CPUSeconds" if you don't like
> "work".)

I agree the naming is not the best, but the way I think of if they are both work just done on different threads.  More thought required.

> *time

Ugh, I've got comment spellchecking turned on in emacs now but I still manage to do this.  Thanks for the proofreading.
Updated patch.
Attachment #8869076 - Attachment is obsolete: true
Attachment #8869388 - Flags: review+
Comment on attachment 8869388 [details] [diff] [review]
bug1309651-record-parallel-time v2

Requesting data review for the new telemetry histogram.
Attachment #8869388 - Flags: review?(benjamin)
Comment on attachment 8869388 [details] [diff] [review]
bug1309651-record-parallel-time v2

>diff --git a/toolkit/components/telemetry/Histograms.json b/toolkit/components/telemetry/Histograms.json

>+  "GC_SLOW_TASK": {
>+    "record_in_processes": ["main", "content"],
>+    "alert_emails": ["dev-telemetry-gc-alerts@mozilla.org","jcoppeard@mozilla.com"],
>+    "expires_in_version": "never",
>+    "kind": "enumerated",
>+    "n_values": 75,
>+    "description": "The longest parallel task in any slice that goes over 2x the budget",
>+    "bug_numbers": [1309651]
>+  },

What do the values (0-74) recorded in this histogram actually mean? If there is a c++ enumeration, can you mention it in the histogram description so that it's self-documenting?
Flags: needinfo?(jcoppeard)
Updated histogram descriptions to point to the definition of the stats phases in the source.
Attachment #8869388 - Attachment is obsolete: true
Attachment #8869388 - Flags: review?(benjamin)
Flags: needinfo?(jcoppeard)
Attachment #8871273 - Flags: review+
Comment on attachment 8871273 [details] [diff] [review]
bug1309651-record-parallel-time v3

Requesting data review on updated patch.
Attachment #8871273 - Flags: review?(benjamin)
Attachment #8871273 - Flags: review?(benjamin) → review+
Pushed by jcoppeard@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/aa7d860d9773
Record time taken by GC parallel tasks r=sfink data-r=bsmedberg
https://hg.mozilla.org/mozilla-central/rev/aa7d860d9773
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
You need to log in before you can comment on or make changes to this bug.