1309651 - Record cpu time spent in GC helper threads

Status: RESOLVED FIXED

(Core :: JavaScript: GC, defect)

Description

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

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.

Comment 1

[Jon Coppeard (:jonco)]

Attachment: bug1309651-record-parallel-time

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.

Comment 2

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

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!

Comment 3

[Jon Coppeard (:jonco)]

(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.

Comment 4

[Jon Coppeard (:jonco)]

Attachment: bug1309651-record-parallel-time v2

Updated patch.

Comment 5

[Jon Coppeard (:jonco)]

Comment on attachment 8869388 [details] [diff] [review]
bug1309651-record-parallel-time v2

Requesting data review for the new telemetry histogram.

Comment 6

[Benjamin Smedberg]

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": ["[e-mail]","[e-mail]"],
>+    "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?

Comment 7

[Jon Coppeard (:jonco)]

Attachment: bug1309651-record-parallel-time v3

Updated histogram descriptions to point to the definition of the stats phases in the source.

Comment 8

[Jon Coppeard (:jonco)]

Comment on attachment 8871273 [details] [diff] [review]
bug1309651-record-parallel-time v3

Requesting data review on updated patch.

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/aa7d860d9773
Record time taken by GC parallel tasks r=sfink data-r=bsmedberg

Comment 10

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/aa7d860d9773