Bug 781945 - Improve GC telemetry (r=mccr8)
authorBill McCloskey <wmccloskey@mozilla.com>
Mon, 13 Aug 2012 10:30:44 -0700
changeset 107694 65bc2e5b574f11c4f0aaf91e44ff0722bddc84ce
parent 107693 356689768e3f9dcae8468e69d867ebdd239e9d50
child 107695 762b97255eed8c0504ac5ef7a4dafdf9bbba502f
push id1490
push userakeybl@mozilla.com
push dateMon, 08 Oct 2012 18:29:50 +0000
treeherdermozilla-beta@f335e7dacdc1 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmccr8
bugs781945
milestone17.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 781945 - Improve GC telemetry (r=mccr8)
js/src/gc/Statistics.cpp
js/src/gc/Statistics.h
js/src/jsfriendapi.h
js/xpconnect/src/XPCJSRuntime.cpp
toolkit/components/telemetry/TelemetryHistograms.h
--- a/js/src/gc/Statistics.cpp
+++ b/js/src/gc/Statistics.cpp
@@ -308,25 +308,32 @@ static void
 FormatPhaseTimes(StatisticsSerializer &ss, const char *name, int64_t *times)
 {
     ss.beginObject(name);
     for (unsigned i = 0; phases[i].name; i++)
         ss.appendIfNonzeroMS(phases[i].name, t(times[phases[i].index]));
     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);
 
     ss.beginObject(NULL);
     if (ss.isJSON())
         ss.appendNumber("Timestamp", "%llu", "", (unsigned long long)timestamp);
     ss.appendDecimal("Total Time", "ms", t(total));
@@ -446,36 +453,33 @@ Statistics::~Statistics()
             }
         }
 
         if (fp != stdout && fp != stderr)
             fclose(fp);
     }
 }
 
-int64_t
-Statistics::gcDuration()
-{
-    return slices.back().end - slices[0].start;
-}
-
 void
 Statistics::printStats()
 {
     if (fullFormat) {
         StatisticsSerializer ss(StatisticsSerializer::AsText);
         formatData(ss, 0);
         char *msg = ss.finishCString();
         if (msg) {
             fprintf(fp, "GC(T+%.3fs) %s\n", t(slices[0].start - startupTime) / 1000.0, msg);
             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]));
     }
     fflush(fp);
 }
 
 void
 Statistics::beginGC()
@@ -496,20 +500,26 @@ Statistics::endGC()
 {
     Probes::GCEnd();
     crash::SnapshotGCStack();
 
     for (int i = 0; i < PHASE_LIMIT; i++)
         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);
 
         double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
         (*cb)(JS_TELEMETRY_GC_MMU_50, mmu50 * 100);
     }
 
     if (fp)
--- a/js/src/gc/Statistics.h
+++ b/js/src/gc/Statistics.h
@@ -132,17 +132,17 @@ struct Statistics {
     unsigned int counts[STAT_LIMIT];
 
     /* Allocated space before the GC started. */
     size_t preBytes;
 
     void beginGC();
     void endGC();
 
-    int64_t gcDuration();
+    void gcDuration(int64_t *total, int64_t *maxPause);
     void printStats();
     bool formatData(StatisticsSerializer &ss, uint64_t timestamp);
 
     double computeMMU(int64_t resolution);
 };
 
 struct AutoGCSlice {
     AutoGCSlice(Statistics &stats, int collectedCount, int compartmentCount, gcreason::Reason reason
--- a/js/src/jsfriendapi.h
+++ b/js/src/jsfriendapi.h
@@ -70,18 +70,21 @@ JS_IsDeadWrapper(JSObject *obj);
  */
 extern JS_FRIEND_API(void)
 JS_TraceShapeCycleCollectorChildren(JSTracer *trc, void *shape);
 
 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_TELEMETRY_GC_INCREMENTAL_DISABLED,
     JS_TELEMETRY_GC_NON_INCREMENTAL
 };
 
 typedef void
--- a/js/xpconnect/src/XPCJSRuntime.cpp
+++ b/js/xpconnect/src/XPCJSRuntime.cpp
@@ -2018,22 +2018,31 @@ AccumulateTelemetryCallback(int id, uint
         Telemetry::Accumulate(Telemetry::GC_REASON_2, sample);
         break;
       case JS_TELEMETRY_GC_IS_COMPARTMENTAL:
         Telemetry::Accumulate(Telemetry::GC_IS_COMPARTMENTAL, sample);
         break;
       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;
       case JS_TELEMETRY_GC_MMU_50:
         Telemetry::Accumulate(Telemetry::GC_MMU_50, sample);
         break;
       case JS_TELEMETRY_GC_RESET:
         Telemetry::Accumulate(Telemetry::GC_RESET, sample);
--- a/toolkit/components/telemetry/TelemetryHistograms.h
+++ b/toolkit/components/telemetry/TelemetryHistograms.h
@@ -47,18 +47,21 @@ HISTOGRAM(CYCLE_COLLECTOR_CONTENT_UNBIND
 HISTOGRAM(FORGET_SKIPPABLE_MAX, 1, 10000, 50, EXPONENTIAL, "Max time spent on one forget skippable (ms)")
 
 /**
  * GC telemetry
  */
 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?")
 HISTOGRAM_BOOLEAN(GC_INCREMENTAL_DISABLED, "Is incremental GC permanently disabled?")
 HISTOGRAM_BOOLEAN(GC_NON_INCREMENTAL, "Was the GC non-incremental?")
 
 HISTOGRAM(TELEMETRY_PING, 1, 3000, 10, EXPONENTIAL, "Time taken to submit telemetry info (ms)")
 HISTOGRAM_BOOLEAN(TELEMETRY_SUCCESS,  "Successful telemetry submission")