Bug 781945 - Improve GC telemetry (r=mccr8)

js/src/gc/Statistics.cpp

@@ -313,15 +313,22 @@ FormatPhaseTimes(StatisticsSerializer &ss, const char *name, int64_t *times)
     ss.endObject();
 }
 
+void
+Statistics::gcDuration(int64_t *total, int64_t *maxPause)
+{
+    *total = *maxPause = 0;
+    for (SliceData *slice = slices.begin(); slice != slices.end(); slice++) {
+        *total += slice->duration();
+        if (slice->duration() > *maxPause)
+            *maxPause = slice->duration();
+    }
+}
+
 bool
 Statistics::formatData(StatisticsSerializer &ss, uint64_t timestamp)
 {
-    int64_t total = 0, longest = 0;
-    for (SliceData *slice = slices.begin(); slice != slices.end(); slice++) {
-        total += slice->duration();
-        if (slice->duration() > longest)
-            longest = slice->duration();
-    }
+    int64_t total, longest;
+    gcDuration(&total, &longest);
 
     double mmu20 = computeMMU(20 * PRMJ_USEC_PER_MSEC);
     double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
@@ -451,12 +458,6 @@ Statistics::~Statistics()
     }
 }
 
-int64_t
-Statistics::gcDuration()
-{
-    return slices.back().end - slices[0].start;
-}
-
 void
 Statistics::printStats()
 {
@@ -469,8 +470,11 @@ Statistics::printStats()
             js_free(msg);
         }
     } else {
+        int64_t total, longest;
+        gcDuration(&total, &longest);
+
         fprintf(fp, "%f %f %f\n",
-                t(gcDuration()),
+                t(total),
                 t(phaseTimes[PHASE_MARK]),
                 t(phaseTimes[PHASE_SWEEP]));
     }
@@ -501,10 +505,16 @@ Statistics::endGC()
         phaseTotals[i] += phaseTimes[i];
 
     if (JSAccumulateTelemetryDataCallback cb = runtime->telemetryCallback) {
+        int64_t total, longest;
+        gcDuration(&total, &longest);
+
         (*cb)(JS_TELEMETRY_GC_IS_COMPARTMENTAL, collectedCount == compartmentCount ? 0 : 1);
-        (*cb)(JS_TELEMETRY_GC_MS, t(gcDuration()));
+        (*cb)(JS_TELEMETRY_GC_MS, t(total));
+        (*cb)(JS_TELEMETRY_GC_MAX_PAUSE_MS, t(longest));
         (*cb)(JS_TELEMETRY_GC_MARK_MS, t(phaseTimes[PHASE_MARK]));
         (*cb)(JS_TELEMETRY_GC_SWEEP_MS, t(phaseTimes[PHASE_SWEEP]));
+        (*cb)(JS_TELEMETRY_GC_MARK_ROOTS_MS, t(phaseTimes[PHASE_MARK_ROOTS]));
+        (*cb)(JS_TELEMETRY_GC_MARK_GRAY_MS, t(phaseTimes[PHASE_MARK_GRAY]));
         (*cb)(JS_TELEMETRY_GC_NON_INCREMENTAL, !!nonincrementalReason);
         (*cb)(JS_TELEMETRY_GC_INCREMENTAL_DISABLED, !runtime->gcIncrementalEnabled);
 

js/src/gc/Statistics.h

@@ -137,7 +137,7 @@ struct Statistics {
     void beginGC();
     void endGC();
 
-    int64_t gcDuration();
+    void gcDuration(int64_t *total, int64_t *maxPause);
     void printStats();
     bool formatData(StatisticsSerializer &ss, uint64_t timestamp);
 

js/src/jsfriendapi.h

@@ -75,8 +75,11 @@ enum {
     JS_TELEMETRY_GC_REASON,
     JS_TELEMETRY_GC_IS_COMPARTMENTAL,
     JS_TELEMETRY_GC_MS,
+    JS_TELEMETRY_GC_MAX_PAUSE_MS,
     JS_TELEMETRY_GC_MARK_MS,
     JS_TELEMETRY_GC_SWEEP_MS,
+    JS_TELEMETRY_GC_MARK_ROOTS_MS,
+    JS_TELEMETRY_GC_MARK_GRAY_MS,
     JS_TELEMETRY_GC_SLICE_MS,
     JS_TELEMETRY_GC_MMU_50,
     JS_TELEMETRY_GC_RESET,

js/xpconnect/src/XPCJSRuntime.cpp

@@ -2023,12 +2023,21 @@ AccumulateTelemetryCallback(int id, uint32_t sample)
       case JS_TELEMETRY_GC_MS:
         Telemetry::Accumulate(Telemetry::GC_MS, sample);
         break;
+      case JS_TELEMETRY_GC_MAX_PAUSE_MS:
+        Telemetry::Accumulate(Telemetry::GC_MAX_PAUSE_MS, sample);
+        break;
       case JS_TELEMETRY_GC_MARK_MS:
         Telemetry::Accumulate(Telemetry::GC_MARK_MS, sample);
         break;
       case JS_TELEMETRY_GC_SWEEP_MS:
         Telemetry::Accumulate(Telemetry::GC_SWEEP_MS, sample);
         break;
+      case JS_TELEMETRY_GC_MARK_ROOTS_MS:
+        Telemetry::Accumulate(Telemetry::GC_MARK_ROOTS_MS, sample);
+        break;
+      case JS_TELEMETRY_GC_MARK_GRAY_MS:
+        Telemetry::Accumulate(Telemetry::GC_MARK_GRAY_MS, sample);
+        break;
       case JS_TELEMETRY_GC_SLICE_MS:
         Telemetry::Accumulate(Telemetry::GC_SLICE_MS, sample);
         break;

toolkit/components/telemetry/TelemetryHistograms.h

@@ -52,8 +52,11 @@ HISTOGRAM(FORGET_SKIPPABLE_MAX, 1, 10000, 50, EXPONENTIAL, "Max time spent on on
 HISTOGRAM_ENUMERATED_VALUES(GC_REASON_2, js::gcreason::NUM_TELEMETRY_REASONS, "Reason (enum value) for initiating a GC")
 HISTOGRAM_BOOLEAN(GC_IS_COMPARTMENTAL, "Is it a compartmental GC?")
 HISTOGRAM(GC_MS, 1, 10000, 50, EXPONENTIAL, "Time spent running JS GC (ms)")
+HISTOGRAM(GC_MAX_PAUSE_MS, 1, 1000, 50, LINEAR, "Longest GC slice in a GC (ms)")
 HISTOGRAM(GC_MARK_MS, 1, 10000, 50, EXPONENTIAL, "Time spent running JS GC mark phase (ms)")
 HISTOGRAM(GC_SWEEP_MS, 1, 10000, 50, EXPONENTIAL, "Time spent running JS GC sweep phase (ms)")
+HISTOGRAM(GC_MARK_ROOTS_MS, 1, 200, 50, LINEAR, "Time spent marking GC roots (ms)")
+HISTOGRAM(GC_MARK_GRAY_MS, 1, 200, 50, LINEAR, "Time spent marking gray GC objects (ms)")
 HISTOGRAM(GC_SLICE_MS, 1, 10000, 50, EXPONENTIAL, "Time spent running a JS GC slice (ms)")
 HISTOGRAM(GC_MMU_50, 1, 100, 20, LINEAR, "Minimum percentage of time spent outside GC over any 50ms window")
 HISTOGRAM_BOOLEAN(GC_RESET, "Was an incremental GC canceled?")