Bug 783147 - Collect telemetry for SCC GC sweeping (r=mccr8)

js/src/gc/Statistics.cpp

@@ -324,12 +324,25 @@ Statistics::gcDuration(int64_t *total, int64_t *maxPause)
     }
 }
 
+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);
 
@@ -341,6 +354,8 @@ Statistics::formatData(StatisticsSerializer &ss, uint64_t timestamp)
     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
@@ -488,6 +503,7 @@ Statistics::beginGC()
     PodArrayZero(phaseTimes);
 
     slices.clearAndFree();
+    sccTimes.clearAndFree();
     nonincrementalReason = NULL;
 
     preBytes = runtime->gcBytes;
@@ -508,6 +524,9 @@ Statistics::endGC()
         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));
@@ -517,6 +536,8 @@ Statistics::endGC()
         (*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);
@@ -605,6 +626,21 @@ Statistics::endPhase(Phase phase)
         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

js/src/gc/Statistics.h

@@ -80,6 +80,9 @@ struct Statistics {
         counts[s]++;
     }
 
+    int64_t beginSCC();
+    void endSCC(unsigned scc, int64_t start);
+
     jschar *formatMessage();
     jschar *formatJSON(uint64_t timestamp);
 
@@ -134,10 +137,14 @@ struct Statistics {
     /* 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);
 
@@ -168,6 +175,17 @@ struct AutoPhase {
     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 */
 

js/src/jscompartment.h

@@ -300,6 +300,9 @@ struct JSCompartment
     size_t                       gcMallocAndFreeBytes;
     size_t                       gcTriggerMallocAndFreeBytes;
 
+    /* During GC, stores the index of this compartment in rt->compartments. */
+    unsigned                     index;
+
   private:
     /*
      * Malloc counter to measure memory pressure for GC scheduling. It runs from

js/src/jsfriendapi.h

@@ -84,7 +84,9 @@ enum {
     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

js/src/jsgc.cpp

@@ -3482,6 +3482,141 @@ ValidateIncrementalMarking(JSRuntime *rt)
 }
 #endif
 
+/*
+ * If compartment A has an edge to an unmarked object in compartment B, then we
+ * must not sweep A in a later slice than we sweep B. That's because a write
+ * barrier in A that could lead to the unmarked object in B becoming
+ * marked. However, if we had already swept that object, we would be in trouble.
+ *
+ * If we consider these dependencies as a graph, then all the compartments in
+ * any strongly-connected component of this graph must be swept in the same
+ * slice. This class is used to compute these strongly connected components via
+ * Tarjan's algorithm.
+ */
+class PartitionCompartments
+{
+    typedef unsigned Node;
+    typedef Vector<Node, 0, SystemAllocPolicy> NodeVector;
+    typedef Vector<bool, 0, SystemAllocPolicy> BoolVector;
+
+    static const Node Undefined = Node(-1);
+
+    JSRuntime *runtime;
+
+    /*
+     * The value of clock ticks monotonically upward as each new compartment is
+     * discovered by the algorithm. When a new SCC is found, it is assigned a
+     * number from nextSCC.
+     */
+    Node clock, nextSCC;
+
+    /*
+     * Compartments have an index based on their order in rt->compartments. The
+     * index is used as a subscript into the arrays below.
+     *
+     * discoveryTime[comp]: The |clock| value when comp was first explored.
+     * lowLink[comp]: The minimal discovery time of any compartment reachable
+     *                from |comp|.
+     * stack: List of explored compartments that haven't been assigned to an SCC.
+     * scc[comp]: SCC number that |comp| is in.
+     * onStack[comp]: Whether |comp| in in |stack|.
+     */
+    NodeVector discoveryTime, lowLink, stack, scc;
+    BoolVector onStack;
+
+    bool fail_;
+
+    void processNode(Node v);
+    void fail() { fail_ = true; }
+    bool failed() { return fail_; }
+
+  public:
+    PartitionCompartments(JSRuntime *rt);
+    void partition();
+    unsigned getSCC(JSCompartment *comp) { return failed() ? 0 : scc[comp->index]; }
+};
+
+const PartitionCompartments::Node PartitionCompartments::Undefined;
+
+PartitionCompartments::PartitionCompartments(JSRuntime *rt)
+  : runtime(rt), clock(0), nextSCC(0), fail_(false)
+{
+    size_t n = runtime->compartments.length();
+    if (!discoveryTime.reserve(n) ||
+        !lowLink.reserve(n) ||
+        !scc.reserve(n) ||
+        !onStack.reserve(n) ||
+        !stack.reserve(n))
+    {
+        fail();
+        return;
+    }
+
+    for (Node v = 0; v < runtime->compartments.length(); v++) {
+        runtime->compartments[v]->index = v;
+        discoveryTime.infallibleAppend(Undefined);
+        lowLink.infallibleAppend(Undefined);
+        scc.infallibleAppend(Undefined);
+        onStack.infallibleAppend(false);
+    }
+}
+
+/* See the Wikipedia article "Tarjan's strongly connected components algorithm". */
+void
+PartitionCompartments::processNode(Node v)
+{
+    int stackDummy;
+    if (failed() || !JS_CHECK_STACK_SIZE(js::GetNativeStackLimit(runtime), &stackDummy)) {
+        fail();
+        return;
+    }
+
+    discoveryTime[v] = clock;
+    lowLink[v] = clock;
+    clock++;
+    stack.infallibleAppend(v);
+    onStack[v] = true;
+
+    JSCompartment *comp = runtime->compartments[v];
+
+    for (WrapperMap::Enum e(comp->crossCompartmentWrappers); !e.empty(); e.popFront()) {
+        if (e.front().key.kind == CrossCompartmentKey::StringWrapper)
+            continue;
+
+        Cell *other = e.front().key.wrapped;
+        if (other->isMarked(BLACK) && !other->isMarked(GRAY))
+            continue;
+
+        Node w = other->compartment()->index;
+
+        if (discoveryTime[w] == Undefined) {
+            processNode(w);
+            lowLink[v] = Min(lowLink[v], lowLink[w]);
+        } else if (onStack[w]) {
+            lowLink[v] = Min(lowLink[v], discoveryTime[w]);
+        }
+    }
+
+    if (lowLink[v] == discoveryTime[v]) {
+        Node w;
+        do {
+            w = stack.popCopy();
+            onStack[w] = false;
+            scc[w] = nextSCC;
+        } while (w != v);
+        nextSCC++;
+    }
+}
+
+void
+PartitionCompartments::partition()
+{
+    for (Node n = 0; n < runtime->compartments.length(); n++) {
+        if (discoveryTime[n] == Undefined)
+            processNode(n);
+    }
+}
+
 static void
 BeginSweepPhase(JSRuntime *rt)
 {
@@ -3542,6 +3677,9 @@ BeginSweepPhase(JSRuntime *rt)
     /* Detach unreachable debuggers and global objects from each other. */
     Debugger::sweepAll(&fop);
 
+    PartitionCompartments partition(rt);
+    partition.partition();
+
     {
         gcstats::AutoPhase ap(rt->gcStats, gcstats::PHASE_SWEEP_COMPARTMENTS);
 
@@ -3554,6 +3692,7 @@ BeginSweepPhase(JSRuntime *rt)
 
         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
@@ -3569,14 +3708,22 @@ BeginSweepPhase(JSRuntime *rt)
      *
      * 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;

js/xpconnect/src/XPCJSRuntime.cpp

@@ -2073,6 +2073,12 @@ AccumulateTelemetryCallback(int id, uint32_t sample)
       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;
     }
 }
 

toolkit/components/telemetry/TelemetryHistograms.h

@@ -62,6 +62,8 @@ HISTOGRAM(GC_MMU_50, 1, 100, 20, LINEAR, "Minimum percentage of time spent outsi
 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")