Bug 1088831 - Count storebuffer overflows, account for minor GCs, and implement timed regions, r=jonco

--HG--
extra : rebase_source : 45985b1dd8f4ee69ea992bdbd1b25746bfb17ffd

js/src/gc/Statistics.cpp

@@ -27,6 +27,7 @@ using namespace js::gc;
 using namespace js::gcstats;
 
 using mozilla::PodArrayZero;
+using mozilla::PodZero;
 
 /* Except for the first and last, slices of less than 10ms are not reported. */
 static const int64_t SLICE_MIN_REPORT_TIME = 10 * PRMJ_USEC_PER_MSEC;
@@ -283,6 +284,7 @@ struct PhaseInfo
 static const Phase PHASE_NO_PARENT = PHASE_LIMIT;
 
 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 },
@@ -326,6 +328,7 @@ static const PhaseInfo phases[] = {
         { PHASE_COMPACT_UPDATE, "Compact Update", PHASE_COMPACT, },
             { PHASE_COMPACT_UPDATE_CELLS, "Compact Update Cells", PHASE_COMPACT_UPDATE, },
     { PHASE_GC_END, "End Callback", PHASE_NO_PARENT },
+    { PHASE_MINOR_GC, "Minor GC", PHASE_NO_PARENT },
     { PHASE_LIMIT, nullptr, PHASE_NO_PARENT }
 };
 
@@ -385,6 +388,7 @@ Statistics::formatData(StatisticsSerializer &ss, uint64_t timestamp)
     ss.appendNumber("Total Zones", "%d", "", zoneStats.zoneCount);
     ss.appendNumber("Total Compartments", "%d", "", zoneStats.compartmentCount);
     ss.appendNumber("Minor GCs", "%d", "", counts[STAT_MINOR_GC]);
+    ss.appendNumber("Store Buffer Overflows", "%d", "", counts[STAT_STOREBUFFER_OVERFLOW]);
     ss.appendNumber("MMU (20ms)", "%d", "%", int(mmu20 * 100));
     ss.appendNumber("MMU (50ms)", "%d", "%", int(mmu50 * 100));
     ss.appendDecimal("SCC Sweep Total", "ms", t(sccTotal));
@@ -476,6 +480,7 @@ Statistics::formatDescription()
   Zones Collected: %d of %d\n\
   Compartments Collected: %d of %d\n\
   MinorGCs since last GC: %d\n\
+  Store Buffer Overflows: %d\n\
   MMU 20ms:%.1f%%; 50ms:%.1f%%\n\
   SCC Sweep Total (MaxPause): %.3fms (%.3fms)\n\
   HeapSize: %.3f MiB\n\
@@ -491,6 +496,7 @@ Statistics::formatDescription()
                 zoneStats.collectedZoneCount, zoneStats.zoneCount,
                 zoneStats.collectedCompartmentCount, zoneStats.compartmentCount,
                 counts[STAT_MINOR_GC],
+                counts[STAT_STOREBUFFER_OVERFLOW],
                 mmu20 * 100., mmu50 * 100.,
                 t(sccTotal), t(sccLongest),
                 double(preBytes) / 1024. / 1024.,
@@ -633,6 +639,8 @@ Statistics::Statistics(JSRuntime *rt)
     fullFormat(false),
     gcDepth(0),
     nonincrementalReason(nullptr),
+    timingMutator(false),
+    timedGCStart(0),
     preBytes(0),
     maxPauseInInterval(0),
     phaseNestingDepth(0),
@@ -640,6 +648,8 @@ Statistics::Statistics(JSRuntime *rt)
 {
     PodArrayZero(phaseTotals);
     PodArrayZero(counts);
+    PodArrayZero(phaseStartTimes);
+    PodArrayZero(phaseTimes);
 
     char *env = getenv("MOZ_GCTIMER");
     if (!env || strcmp(env, "none") == 0) {
@@ -723,9 +733,6 @@ Statistics::printStats()
 void
 Statistics::beginGC(JSGCInvocationKind kind)
 {
-    PodArrayZero(phaseStartTimes);
-    PodArrayZero(phaseTimes);
-
     slices.clearAndFree();
     sccTimes.clearAndFree();
     gckind = kind;
@@ -767,6 +774,11 @@ Statistics::endGC()
 
     if (fp)
         printStats();
+
+    // Clear the timers at the end of a GC because we accumulate time in
+    // between GCs for some (which come before PHASE_GC_BEGIN in the list.)
+    PodZero(&phaseStartTimes[PHASE_GC_BEGIN], PHASE_LIMIT - PHASE_GC_BEGIN);
+    PodZero(&phaseTimes[PHASE_GC_BEGIN], PHASE_LIMIT - PHASE_GC_BEGIN);
 }
 
 void
@@ -823,20 +835,60 @@ Statistics::endSlice()
         PodArrayZero(counts);
 }
 
+void
+Statistics::startTimingMutator()
+{
+    MOZ_ASSERT(!timingMutator);
+
+    // Should only be called from outside of GC
+    MOZ_ASSERT(phaseNestingDepth == 0);
+
+    timingMutator = true;
+    timedGCTime = 0;
+    phaseStartTimes[PHASE_MUTATOR] = 0;
+    phaseTimes[PHASE_MUTATOR] = 0;
+    timedGCStart = 0;
+
+    beginPhase(PHASE_MUTATOR);
+}
+
+void
+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);
+
+    endPhase(PHASE_MUTATOR);
+    mutator_ms = t(phaseTimes[PHASE_MUTATOR]);
+    gc_ms = t(timedGCTime);
+    timingMutator = false;
+}
+
 void
 Statistics::beginPhase(Phase phase)
 {
     /* Guard against re-entry */
     MOZ_ASSERT(!phaseStartTimes[phase]);
 
+    if (timingMutator) {
+        if (phaseNestingDepth == 1 && phaseNesting[0] == PHASE_MUTATOR) {
+            endPhase(PHASE_MUTATOR);
+            timedGCStart = PRMJ_Now();
+        }
+    }
+
 #ifdef DEBUG
     MOZ_ASSERT(phases[phase].index == phase);
     Phase parent = phaseNestingDepth ? phaseNesting[phaseNestingDepth - 1] : PHASE_NO_PARENT;
     MOZ_ASSERT(phaseNestingDepth < MAX_NESTING);
-    MOZ_ASSERT_IF(gcDepth == 1, phases[phase].parent == parent);
+    // 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++;
-#endif
 
     phaseStartTimes[phase] = PRMJ_Now();
 }
@@ -846,10 +898,19 @@ Statistics::endPhase(Phase phase)
 {
     phaseNestingDepth--;
 
-    int64_t t = PRMJ_Now() - phaseStartTimes[phase];
+    int64_t now = PRMJ_Now();
-    slices.back().phaseTimes[phase] += t;
+    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) {
+            timedGCTime += now - timedGCStart;
+            beginPhase(PHASE_MUTATOR);
+        }
+    }
 }
 
 void

js/src/gc/Statistics.h

@@ -27,6 +27,7 @@ class GCParallelTask;
 namespace gcstats {
 
 enum Phase {
+    PHASE_MUTATOR,
     PHASE_GC_BEGIN,
     PHASE_WAIT_BACKGROUND_THREAD,
     PHASE_MARK_DISCARD_CODE,
@@ -70,6 +71,7 @@ enum Phase {
     PHASE_COMPACT_UPDATE,
     PHASE_COMPACT_UPDATE_CELLS,
     PHASE_GC_END,
+    PHASE_MINOR_GC,
 
     PHASE_LIMIT
 };
@@ -79,6 +81,10 @@ enum Stat {
     STAT_DESTROY_CHUNK,
     STAT_MINOR_GC,
 
+    // Number of times a 'put' into a storebuffer overflowed, triggering a
+    // compaction
+    STAT_STOREBUFFER_OVERFLOW,
+
     STAT_LIMIT
 };
 
@@ -118,6 +124,9 @@ struct Statistics
                     JS::gcreason::Reason reason);
     void endSlice();
 
+    void startTimingMutator();
+    void stopTimingMutator(double &mutator_ms, double &gc_ms);
+
     void reset(const char *reason) { slices.back().resetReason = reason; }
     void nonincremental(const char *reason) { nonincrementalReason = reason; }
 
@@ -179,6 +188,13 @@ struct Statistics
     /* 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];
 
@@ -194,12 +210,10 @@ struct Statistics
     /* Records the maximum GC pause in an API-controlled interval (in us). */
     int64_t maxPauseInInterval;
 
-#ifdef DEBUG
     /* Phases that are currently on stack. */
     static const size_t MAX_NESTING = 8;
     Phase phaseNesting[MAX_NESTING];
-#endif
+    size_t phaseNestingDepth;
-    mozilla::DebugOnly<size_t> phaseNestingDepth;
 
     /* Sweep times for SCCs of compartments. */
     Vector<int64_t, 0, SystemAllocPolicy> sccTimes;

js/src/gc/StoreBuffer.cpp

@@ -10,6 +10,7 @@
 
 #include "mozilla/Assertions.h"
 
+#include "gc/Statistics.h"
 #include "vm/ArgumentsObject.h"
 #include "vm/ForkJoin.h"
 
@@ -181,7 +182,10 @@ StoreBuffer::markAll(JSTracer *trc)
 void
 StoreBuffer::setAboutToOverflow()
 {
-    aboutToOverflow_ = true;
+    if (!aboutToOverflow_) {
+        aboutToOverflow_ = true;
+        runtime_->gc.stats.count(gcstats::STAT_STOREBUFFER_OVERFLOW);
+    }
     runtime_->gc.requestMinorGC(JS::gcreason::FULL_STORE_BUFFER);
 }
 

js/src/gc/Verifier.cpp

@@ -503,7 +503,10 @@ js::gc::GCRuntime::endVerifyPostBarriers()
     if (!edges.init())
         goto oom;
     trc->edges = &edges;
-    storeBuffer.markAll(trc);
+    {
+        gcstats::AutoPhase ap(stats, gcstats::PHASE_MINOR_GC);
+        storeBuffer.markAll(trc);
+    }
 
     /* Walk the heap to find any edges not the the |edges| set. */
     trc->setTraceCallback(PostVerifierVisitEdge);

js/src/jsgc.cpp

@@ -6455,6 +6455,7 @@ void
 GCRuntime::minorGC(JS::gcreason::Reason reason)
 {
 #ifdef JSGC_GENERATIONAL
+    gcstats::AutoPhase ap(stats, gcstats::PHASE_MINOR_GC);
     minorGCRequested = false;
     TraceLogger *logger = TraceLoggerForMainThread(rt);
     AutoTraceLog logMinorGC(logger, TraceLogger::MinorGC);
@@ -6469,6 +6470,7 @@ GCRuntime::minorGC(JSContext *cx, JS::gcreason::Reason reason)
     // Alternate to the runtime-taking form above which allows marking type
     // objects as needing pretenuring.
 #ifdef JSGC_GENERATIONAL
+    gcstats::AutoPhase ap(stats, gcstats::PHASE_MINOR_GC);
     minorGCRequested = false;
     TraceLogger *logger = TraceLoggerForMainThread(rt);
     AutoTraceLog logMinorGC(logger, TraceLogger::MinorGC);

js/src/shell/js.cpp

@@ -1667,6 +1667,43 @@ Quit(JSContext *cx, unsigned argc, jsval *vp)
     return false;
 }
 
+static bool
+StartTimingMutator(JSContext *cx, unsigned argc, jsval *vp)
+{
+    CallArgs args = CallArgsFromVp(argc, vp);
+    if (args.length() > 0) {
+        JS_ReportErrorNumber(cx, my_GetErrorMessage, nullptr,
+                             JSSMSG_TOO_MANY_ARGS, "startTimingMutator");
+        return false;
+    }
+
+    cx->runtime()->gc.stats.startTimingMutator();
+    args.rval().setUndefined();
+    return true;
+}
+
+static bool
+StopTimingMutator(JSContext *cx, unsigned argc, jsval *vp)
+{
+    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);
+    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;
+}
+
 static const char *
 ToSource(JSContext *cx, MutableHandleValue vp, JSAutoByteString *bytes)
 {
@@ -4246,6 +4283,14 @@ static const JSFunctionSpecWithHelp shell_functions[] = {
 "  Throw if the first two arguments are not the same (both +0 or both -0,\n"
 "  both NaN, or non-zero and ===)."),
 
+    JS_FN_HELP("startTimingMutator", StartTimingMutator, 0, 0,
+"startTimingMutator()",
+"  Start accounting time to mutator vs GC."),
+
+    JS_FN_HELP("stopTimingMutator", StopTimingMutator, 0, 0,
+"stopTimingMutator()",
+"  Stop accounting time to mutator vs GC and dump the results."),
+
     JS_FN_HELP("throwError", ThrowError, 0, 0,
 "throwError()",
 "  Throw an error from JS_ReportError."),