Bug 1103957 - prevent phase nesting, r=terrence
authorSteve Fink <sfink@mozilla.com>
Tue, 09 Dec 2014 14:59:11 -0800
changeset 220052 df0850b9023b6dfaead4817cfc3e42902a8ec496
parent 220051 b5b1a8e8aee4c94b1dc2e60e751343afdeb6f72c
child 220053 b7eb1ce0237d6125b75bc8ff1cb3afc328d6e78c
child 220054 89c76328ade6f016dcc86591fcdfd43fca8c9aeb
push id27974
push userdgohman@mozilla.com
push dateWed, 17 Dec 2014 00:41:35 +0000
treeherdermozilla-central@b7eb1ce0237d [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersterrence
bugs1103957
milestone37.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 1103957 - prevent phase nesting, r=terrence
js/src/gc/Statistics.cpp
js/src/gc/Statistics.h
js/src/shell/js.cpp
--- a/js/src/gc/Statistics.cpp
+++ b/js/src/gc/Statistics.cpp
@@ -278,16 +278,23 @@ struct PhaseInfo
 {
     Phase index;
     const char *name;
     Phase parent;
 };
 
 static const Phase PHASE_NO_PARENT = PHASE_LIMIT;
 
+/*
+ * Note that PHASE_MUTATOR, PHASE_GC_BEGIN, and PHASE_GC_END never have any
+ * child phases. If beginPhase is called while one of these is active, they
+ * will automatically be suspended and resumed when the phase stack is next
+ * empty. Timings for these phases are thus exclusive of any other phase.
+ */
+
 static const PhaseInfo phases[] = {
     { PHASE_MUTATOR, "Mutator Running", PHASE_NO_PARENT },
     { PHASE_GC_BEGIN, "Begin Callback", PHASE_NO_PARENT },
     { PHASE_WAIT_BACKGROUND_THREAD, "Wait Background Thread", PHASE_NO_PARENT },
     { PHASE_MARK_DISCARD_CODE, "Mark Discard Code", PHASE_NO_PARENT },
     { PHASE_PURGE, "Purge", PHASE_NO_PARENT },
     { PHASE_MARK, "Mark", PHASE_NO_PARENT },
         { PHASE_MARK_ROOTS, "Mark Roots", PHASE_MARK },
@@ -634,21 +641,21 @@ Statistics::formatJSON(uint64_t timestam
 
 Statistics::Statistics(JSRuntime *rt)
   : runtime(rt),
     startupTime(PRMJ_Now()),
     fp(nullptr),
     fullFormat(false),
     gcDepth(0),
     nonincrementalReason(nullptr),
-    timingMutator(false),
     timedGCStart(0),
     preBytes(0),
     maxPauseInInterval(0),
     phaseNestingDepth(0),
+    suspendedPhaseNestingDepth(0),
     sliceCallback(nullptr)
 {
     PodArrayZero(phaseTotals);
     PodArrayZero(counts);
     PodArrayZero(phaseStartTimes);
     PodArrayZero(phaseTimes);
 
     char *env = getenv("MOZ_GCTIMER");
@@ -828,88 +835,101 @@ Statistics::endSlice()
     /* Do this after the slice callback since it uses these values. */
     if (last)
         PodArrayZero(counts);
 }
 
 void
 Statistics::startTimingMutator()
 {
-    MOZ_ASSERT(!timingMutator);
-
     // Should only be called from outside of GC
     MOZ_ASSERT(phaseNestingDepth == 0);
+    MOZ_ASSERT(suspendedPhaseNestingDepth == 0);
 
-    timingMutator = true;
     timedGCTime = 0;
     phaseStartTimes[PHASE_MUTATOR] = 0;
     phaseTimes[PHASE_MUTATOR] = 0;
     timedGCStart = 0;
 
     beginPhase(PHASE_MUTATOR);
 }
 
-void
+bool
 Statistics::stopTimingMutator(double &mutator_ms, double &gc_ms)
 {
-    MOZ_ASSERT(timingMutator);
-
-    // Should only be called from outside of GC
-    MOZ_ASSERT(phaseNestingDepth == 1 && phaseNesting[0] == PHASE_MUTATOR);
+    // This should only be called from outside of GC, while timing the mutator.
+    if (phaseNestingDepth != 1 || phaseNesting[0] != PHASE_MUTATOR)
+        return false;
 
     endPhase(PHASE_MUTATOR);
     mutator_ms = t(phaseTimes[PHASE_MUTATOR]);
     gc_ms = t(timedGCTime);
-    timingMutator = false;
+
+    return true;
 }
 
 void
 Statistics::beginPhase(Phase phase)
 {
-    /* Guard against re-entry */
-    MOZ_ASSERT(!phaseStartTimes[phase]);
+    Phase parent = phaseNestingDepth ? phaseNesting[phaseNestingDepth - 1] : PHASE_NO_PARENT;
 
-    if (timingMutator) {
-        if (phaseNestingDepth == 1 && phaseNesting[0] == PHASE_MUTATOR) {
-            endPhase(PHASE_MUTATOR);
-            timedGCStart = PRMJ_Now();
-        }
+    // Re-entry is allowed during callbacks. Do not account nested GC time
+    // against the callbacks.
+    //
+    // Reuse this mechanism for managing PHASE_MUTATOR.
+    if (parent == PHASE_GC_BEGIN || parent == PHASE_GC_END || parent == PHASE_MUTATOR) {
+        suspendedPhases[suspendedPhaseNestingDepth++] = parent;
+        MOZ_ASSERT(suspendedPhaseNestingDepth <= mozilla::ArrayLength(suspendedPhases));
+        endPhase(parent);
+        parent = phaseNestingDepth ? phaseNesting[phaseNestingDepth - 1] : PHASE_NO_PARENT;
     }
 
+    // Guard against any other re-entry.
+    MOZ_ASSERT(!phaseStartTimes[phase]);
+
 #ifdef DEBUG
     MOZ_ASSERT(phases[phase].index == phase);
-    Phase parent = phaseNestingDepth ? phaseNesting[phaseNestingDepth - 1] : PHASE_NO_PARENT;
     MOZ_ASSERT(phaseNestingDepth < MAX_NESTING);
-    // Major and minor GCs can nest inside PHASE_GC_BEGIN/PHASE_GC_END.
     MOZ_ASSERT_IF(gcDepth == 1 && phase != PHASE_MINOR_GC, phases[phase].parent == parent);
 #endif
 
     phaseNesting[phaseNestingDepth] = phase;
     phaseNestingDepth++;
 
     phaseStartTimes[phase] = PRMJ_Now();
 }
 
 void
 Statistics::endPhase(Phase phase)
 {
+    int64_t now = PRMJ_Now();
+
+    if (phase == PHASE_MUTATOR)
+        timedGCStart = now;
+
     phaseNestingDepth--;
 
-    int64_t now = PRMJ_Now();
     int64_t t = now - phaseStartTimes[phase];
     if (!slices.empty())
         slices.back().phaseTimes[phase] += t;
     phaseTimes[phase] += t;
     phaseStartTimes[phase] = 0;
 
-    if (timingMutator) {
-        if (phaseNestingDepth == 0 && phase != PHASE_MUTATOR) {
+    // When emptying the stack, we may need to resume a callback phase
+    // (PHASE_GC_BEGIN/END) or if not, return to timing the mutator
+    // (PHASE_MUTATOR).
+    //
+    // However, if the phase we're ending is PHASE_MUTATOR, that means
+    // beginPhase is calling endPhase(PHASE_MUTATOR) because some other phase
+    // is starting. So don't resume any earlier phase.
+    if (phaseNestingDepth == 0 && suspendedPhaseNestingDepth > 0 && phase != PHASE_MUTATOR) {
+        Phase resumePhase = suspendedPhases[--suspendedPhaseNestingDepth];
+        if (resumePhase == PHASE_MUTATOR)
             timedGCTime += now - timedGCStart;
-            beginPhase(PHASE_MUTATOR);
-        }
+        beginPhase(resumePhase);
     }
 }
 
 void
 Statistics::endParallelPhase(Phase phase, const GCParallelTask *task)
 {
     phaseNestingDepth--;
 
--- a/js/src/gc/Statistics.h
+++ b/js/src/gc/Statistics.h
@@ -120,17 +120,17 @@ struct Statistics
     void endPhase(Phase phase);
     void endParallelPhase(Phase phase, const GCParallelTask *task);
 
     void beginSlice(const ZoneGCStats &zoneStats, JSGCInvocationKind gckind,
                     JS::gcreason::Reason reason);
     void endSlice();
 
     void startTimingMutator();
-    void stopTimingMutator(double &mutator_ms, double &gc_ms);
+    bool stopTimingMutator(double &mutator_ms, double &gc_ms);
 
     void reset(const char *reason) { slices.back().resetReason = reason; }
     void nonincremental(const char *reason) { nonincrementalReason = reason; }
 
     void count(Stat s) {
         MOZ_ASSERT(s < STAT_LIMIT);
         counts[s]++;
     }
@@ -183,19 +183,16 @@ struct Statistics
         int64_t duration() const { return end - start; }
     };
 
     Vector<SliceData, 8, SystemAllocPolicy> slices;
 
     /* Most recent time when the given phase started. */
     int64_t phaseStartTimes[PHASE_LIMIT];
 
-    /* Are we currently timing mutator vs GC time? */
-    bool timingMutator;
-
     /* Bookkeeping for GC timings when timingMutator is true */
     int64_t timedGCStart;
     int64_t timedGCTime;
 
     /* Total time in a given phase for this GC. */
     int64_t phaseTimes[PHASE_LIMIT];
 
     /* Total time in a given phase over all GCs. */
@@ -210,16 +207,25 @@ struct Statistics
     /* Records the maximum GC pause in an API-controlled interval (in us). */
     int64_t maxPauseInInterval;
 
     /* Phases that are currently on stack. */
     static const size_t MAX_NESTING = 8;
     Phase phaseNesting[MAX_NESTING];
     size_t phaseNestingDepth;
 
+    /*
+     * To avoid recursive nesting, we discontinue a callback phase when any
+     * other phases are started. Remember what phase to resume when the inner
+     * phases are complete. (And because GCs can nest within the callbacks any
+     * number of times, we need a whole stack of of phases to resume.)
+     */
+    Phase suspendedPhases[MAX_NESTING];
+    size_t suspendedPhaseNestingDepth;
+
     /* Sweep times for SCCs of compartments. */
     Vector<int64_t, 0, SystemAllocPolicy> sccTimes;
 
     JS::GCSliceCallback sliceCallback;
 
     void beginGC(JSGCInvocationKind kind);
     void endGC();
 
--- a/js/src/shell/js.cpp
+++ b/js/src/shell/js.cpp
@@ -1675,17 +1675,20 @@ StopTimingMutator(JSContext *cx, unsigne
     CallArgs args = CallArgsFromVp(argc, vp);
     if (args.length() > 0) {
         JS_ReportErrorNumber(cx, my_GetErrorMessage, nullptr,
                              JSSMSG_TOO_MANY_ARGS, "stopTimingMutator");
         return false;
     }
 
     double mutator_ms, gc_ms;
-    cx->runtime()->gc.stats.stopTimingMutator(mutator_ms, gc_ms);
+    if (!cx->runtime()->gc.stats.stopTimingMutator(mutator_ms, gc_ms)) {
+        JS_ReportError(cx, "stopTimingMutator called when not timing the mutator");
+        return false;
+    }
     double total_ms = mutator_ms + gc_ms;
     if (total_ms > 0) {
         fprintf(gOutFile, "Mutator: %.3fms (%.1f%%), GC: %.3fms (%.1f%%)\n",
                 mutator_ms, mutator_ms / total_ms * 100.0, gc_ms, gc_ms / total_ms * 100.0);
     }
 
     args.rval().setUndefined();
     return true;