Bug 783147 - Send telemetry about SCC GC times (r=mccr8)
authorBill McCloskey <wmccloskey@mozilla.com>
Fri, 17 Aug 2012 10:05:11 -0700
changeset 102662 12753a1a11b85ec41e025203500e80df6c893081
parent 102661 0a70fc2d7d251c83b94b8399dde24865a00d71d8
child 102663 e8427646099454cfb6beeba73e27b595ca65daf6
push id13575
push userwmccloskey@mozilla.com
push dateFri, 17 Aug 2012 17:06:51 +0000
treeherdermozilla-inbound@12753a1a11b8 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmccr8
bugs783147
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 783147 - Send telemetry about SCC GC times (r=mccr8)
js/src/gc/Statistics.cpp
js/src/gc/Statistics.h
js/src/jsfriendapi.h
js/src/jsgc.cpp
js/xpconnect/src/XPCJSRuntime.cpp
toolkit/components/telemetry/TelemetryHistograms.h
--- a/js/src/gc/Statistics.cpp
+++ b/js/src/gc/Statistics.cpp
@@ -319,33 +319,48 @@ Statistics::gcDuration(int64_t *total, i
     *total = *maxPause = 0;
     for (SliceData *slice = slices.begin(); slice != slices.end(); slice++) {
         *total += slice->duration();
         if (slice->duration() > *maxPause)
             *maxPause = slice->duration();
     }
 }
 
+void
+Statistics::sccDurations(int64_t *total, int64_t *maxPause)
+{
+    *total = *maxPause = 0;
+    for (size_t i = 0; i < sccTimes.length(); i++) {
+        *total += sccTimes[i];
+        *maxPause = Max(*maxPause, sccTimes[i]);
+    }
+}
+
 bool
 Statistics::formatData(StatisticsSerializer &ss, uint64_t timestamp)
 {
     int64_t total, longest;
     gcDuration(&total, &longest);
 
+    int64_t sccTotal, sccLongest;
+    sccDurations(&sccTotal, &sccLongest);
+
     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));
     ss.appendNumber("Compartments Collected", "%d", "", collectedCount);
     ss.appendNumber("Total Compartments", "%d", "", compartmentCount);
     ss.appendNumber("MMU (20ms)", "%d", "%", int(mmu20 * 100));
     ss.appendNumber("MMU (50ms)", "%d", "%", int(mmu50 * 100));
+    ss.appendDecimal("SCC Sweep Total", "ms", t(sccTotal));
+    ss.appendDecimal("SCC Sweep Max Pause", "ms", t(sccLongest));
     if (slices.length() > 1 || ss.isJSON())
         ss.appendDecimal("Max Pause", "ms", t(longest));
     else
         ss.appendString("Reason", ExplainReason(slices[0].reason));
     if (nonincrementalReason || ss.isJSON()) {
         ss.appendString("Nonincremental Reason",
                         nonincrementalReason ? nonincrementalReason : "none");
     }
@@ -483,16 +498,17 @@ Statistics::printStats()
 
 void
 Statistics::beginGC()
 {
     PodArrayZero(phaseStartTimes);
     PodArrayZero(phaseTimes);
 
     slices.clearAndFree();
+    sccTimes.clearAndFree();
     nonincrementalReason = NULL;
 
     preBytes = runtime->gcBytes;
 
     Probes::GCStart();
 }
 
 void
@@ -503,25 +519,30 @@ Statistics::endGC()
 
     for (int i = 0; i < PHASE_LIMIT; i++)
         phaseTotals[i] += phaseTimes[i];
 
     if (JSAccumulateTelemetryDataCallback cb = runtime->telemetryCallback) {
         int64_t total, longest;
         gcDuration(&total, &longest);
 
+        int64_t sccTotal, sccLongest;
+        sccDurations(&sccTotal, &sccLongest);
+
         (*cb)(JS_TELEMETRY_GC_IS_COMPARTMENTAL, collectedCount == compartmentCount ? 0 : 1);
         (*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);
+        (*cb)(JS_TELEMETRY_GC_SCC_SWEEP_TOTAL_MS, t(sccTotal));
+        (*cb)(JS_TELEMETRY_GC_SCC_SWEEP_MAX_PAUSE_MS, t(sccLongest));
 
         double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
         (*cb)(JS_TELEMETRY_GC_MMU_50, mmu50 * 100);
     }
 
     if (fp)
         printStats();
 }
@@ -600,16 +621,31 @@ Statistics::endPhase(Phase phase)
     phaseStartTimes[phase] = 0;
 
     if (phase == gcstats::PHASE_MARK)
         Probes::GCEndMarkPhase();
     else if (phase == gcstats::PHASE_SWEEP)
         Probes::GCEndSweepPhase();
 }
 
+int64_t
+Statistics::beginSCC()
+{
+    return PRMJ_Now();
+}
+
+void
+Statistics::endSCC(unsigned scc, int64_t start)
+{
+    if (scc >= sccTimes.length() && !sccTimes.resize(scc + 1))
+        return;
+
+    sccTimes[scc] += PRMJ_Now() - start;
+}
+
 /*
  * MMU (minimum mutator utilization) is a measure of how much garbage collection
  * is affecting the responsiveness of the system. MMU measurements are given
  * with respect to a certain window size. If we report MMU(50ms) = 80%, then
  * that means that, for any 50ms window of time, at least 80% of the window is
  * devoted to the mutator. In other words, the GC is running for at most 20% of
  * the window, or 10ms. The GC can run multiple slices during the 50ms window
  * as long as the total time it spends is at most 10ms.
--- a/js/src/gc/Statistics.h
+++ b/js/src/gc/Statistics.h
@@ -75,16 +75,19 @@ struct Statistics {
     void reset(const char *reason) { slices.back().resetReason = reason; }
     void nonincremental(const char *reason) { nonincrementalReason = reason; }
 
     void count(Stat s) {
         JS_ASSERT(s < STAT_LIMIT);
         counts[s]++;
     }
 
+    int64_t beginSCC();
+    void endSCC(unsigned scc, int64_t start);
+
     jschar *formatMessage();
     jschar *formatJSON(uint64_t timestamp);
 
   private:
     JSRuntime *runtime;
 
     int64_t startupTime;
 
@@ -129,20 +132,24 @@ struct Statistics {
     int64_t phaseTotals[PHASE_LIMIT];
 
     /* Number of events of this type for this GC. */
     unsigned int counts[STAT_LIMIT];
 
     /* Allocated space before the GC started. */
     size_t preBytes;
 
+    /* Sweep times for SCCs of compartments. */
+    Vector<int64_t, 0, SystemAllocPolicy> sccTimes;
+
     void beginGC();
     void endGC();
 
     void gcDuration(int64_t *total, int64_t *maxPause);
+    void sccDurations(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
@@ -163,12 +170,23 @@ struct AutoPhase {
       : stats(stats), phase(phase) { JS_GUARD_OBJECT_NOTIFIER_INIT; stats.beginPhase(phase); }
     ~AutoPhase() { stats.endPhase(phase); }
 
     Statistics &stats;
     Phase phase;
     JS_DECL_USE_GUARD_OBJECT_NOTIFIER
 };
 
+struct AutoSCC {
+    AutoSCC(Statistics &stats, unsigned scc JS_GUARD_OBJECT_NOTIFIER_PARAM)
+      : stats(stats), scc(scc) { JS_GUARD_OBJECT_NOTIFIER_INIT; start = stats.beginSCC(); }
+    ~AutoSCC() { stats.endSCC(scc, start); }
+
+    Statistics &stats;
+    unsigned scc;
+    int64_t start;
+    JS_DECL_USE_GUARD_OBJECT_NOTIFIER
+};
+
 } /* namespace gcstats */
 } /* namespace js */
 
 #endif /* jsgc_statistics_h___ */
--- a/js/src/jsfriendapi.h
+++ b/js/src/jsfriendapi.h
@@ -79,17 +79,19 @@ enum {
     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
+    JS_TELEMETRY_GC_NON_INCREMENTAL,
+    JS_TELEMETRY_GC_SCC_SWEEP_TOTAL_MS,
+    JS_TELEMETRY_GC_SCC_SWEEP_MAX_PAUSE_MS
 };
 
 typedef void
 (* JSAccumulateTelemetryDataCallback)(int id, uint32_t sample);
 
 extern JS_FRIEND_API(void)
 JS_SetAccumulateTelemetryCallback(JSRuntime *rt, JSAccumulateTelemetryDataCallback callback);
 
--- a/js/src/jsgc.cpp
+++ b/js/src/jsgc.cpp
@@ -3687,39 +3687,48 @@ BeginSweepPhase(JSRuntime *rt)
          * Eliminate any garbage values from the VM stack that may have been
          * left by the JIT in between incremental GC slices. We need to do this
          * before discarding analysis data during JSCompartment::sweep.
          */
         rt->stackSpace.markAndClobber(NULL);
 
         bool releaseTypes = ReleaseObservedTypes(rt);
         for (CompartmentsIter c(rt); !c.done(); c.next()) {
+            gcstats::AutoSCC scc(rt->gcStats, partition.getSCC(c));
             if (c->isCollecting())
                 c->sweep(&fop, releaseTypes);
             else
                 c->sweepCrossCompartmentWrappers();
         }
     }
 
     /*
      * Queue all GC things in all compartments for sweeping, either in the
      * foreground or on the background thread.
      *
      * Note that order is important here for the background case.
      *
      * Objects are finalized immediately but this may change in the future.
      */
-    for (GCCompartmentsIter c(rt); !c.done(); c.next())
+    for (GCCompartmentsIter c(rt); !c.done(); c.next()) {
+        gcstats::AutoSCC scc(rt->gcStats, partition.getSCC(c));
         c->arenas.queueObjectsForSweep(&fop);
-    for (GCCompartmentsIter c(rt); !c.done(); c.next())
+    }
+    for (GCCompartmentsIter c(rt); !c.done(); c.next()) {
+        gcstats::AutoSCC scc(rt->gcStats, partition.getSCC(c));
         c->arenas.queueStringsForSweep(&fop);
-    for (GCCompartmentsIter c(rt); !c.done(); c.next())
+    }
+    for (GCCompartmentsIter c(rt); !c.done(); c.next()) {
+        gcstats::AutoSCC scc(rt->gcStats, partition.getSCC(c));
         c->arenas.queueScriptsForSweep(&fop);
-    for (GCCompartmentsIter c(rt); !c.done(); c.next())
+    }
+    for (GCCompartmentsIter c(rt); !c.done(); c.next()) {
+        gcstats::AutoSCC scc(rt->gcStats, partition.getSCC(c));
         c->arenas.queueShapesForSweep(&fop);
+    }
 
     rt->gcSweepPhase = 0;
     rt->gcSweepCompartmentIndex = 0;
     rt->gcSweepKindIndex = 0;
 
     {
         gcstats::AutoPhase ap(rt->gcStats, gcstats::PHASE_FINALIZE_END);
         if (rt->gcFinalizeCallback)
--- a/js/xpconnect/src/XPCJSRuntime.cpp
+++ b/js/xpconnect/src/XPCJSRuntime.cpp
@@ -2068,16 +2068,22 @@ AccumulateTelemetryCallback(int id, uint
         Telemetry::Accumulate(Telemetry::GC_RESET, sample);
         break;
       case JS_TELEMETRY_GC_INCREMENTAL_DISABLED:
         Telemetry::Accumulate(Telemetry::GC_INCREMENTAL_DISABLED, sample);
         break;
       case JS_TELEMETRY_GC_NON_INCREMENTAL:
         Telemetry::Accumulate(Telemetry::GC_NON_INCREMENTAL, sample);
         break;
+      case JS_TELEMETRY_GC_SCC_SWEEP_TOTAL_MS:
+        Telemetry::Accumulate(Telemetry::GC_SCC_SWEEP_TOTAL_MS, sample);
+        break;
+      case JS_TELEMETRY_GC_SCC_SWEEP_MAX_PAUSE_MS:
+        Telemetry::Accumulate(Telemetry::GC_SCC_SWEEP_MAX_PAUSE_MS, sample);
+        break;
     }
 }
 
 static void
 CompartmentNameCallback(JSRuntime *rt, JSCompartment *comp,
                         char *buf, size_t bufsize)
 {
     nsCString name;
--- a/toolkit/components/telemetry/TelemetryHistograms.h
+++ b/toolkit/components/telemetry/TelemetryHistograms.h
@@ -57,16 +57,18 @@ HISTOGRAM(GC_MARK_MS, 1, 10000, 50, EXPO
 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(GC_SCC_SWEEP_TOTAL_MS, 1, 500, 50, LINEAR, "Time spent sweeping compartment SCCs (ms)")
+HISTOGRAM(GC_SCC_SWEEP_MAX_PAUSE_MS, 1, 500, 50, LINEAR, "Time spent sweeping slowest compartment SCC (ms)")
 
 HISTOGRAM(TELEMETRY_PING, 1, 3000, 10, EXPONENTIAL, "Time taken to submit telemetry info (ms)")
 HISTOGRAM_BOOLEAN(TELEMETRY_SUCCESS,  "Successful telemetry submission")
 HISTOGRAM(MEMORY_JS_COMPARTMENTS_SYSTEM, 1, 1000, 50, EXPONENTIAL, "Total JavaScript compartments used for add-ons and internals.")
 HISTOGRAM(MEMORY_JS_COMPARTMENTS_USER, 1, 1000, 50, EXPONENTIAL, "Total JavaScript compartments used for web pages")
 HISTOGRAM(MEMORY_JS_GC_HEAP, 1024, 512 * 1024, 50, EXPONENTIAL, "Memory used by the garbage-collected JavaScript heap (KB)")
 HISTOGRAM(MEMORY_RESIDENT, 32 * 1024, 1024 * 1024, 50, EXPONENTIAL, "Resident memory size (KB)")
 HISTOGRAM(MEMORY_STORAGE_SQLITE, 1024, 512 * 1024, 50, EXPONENTIAL, "Memory used by SQLite (KB)")