Bug 1088831 - Track mutator vs GC time in specified intervals, r=jonco

--HG--
extra : rebase_source : 9a33a646c120df0fb22399c6ea83c0a041bad9f0

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 },
@@ -642,6 +644,8 @@ Statistics::Statistics(JSRuntime *rt)
     fullFormat(false),
     gcDepth(0),
     nonincrementalReason(nullptr),
+    timingMutator(false),
+    timedGCStart(0),
     preBytes(0),
     maxPauseInInterval(0),
     phaseNestingDepth(0),
@@ -778,8 +782,8 @@ Statistics::endGC()
 
     // Clear the timers at the end of a GC because we accumulate time for some
     // phases (eg storebuffer compaction) during the mutator's run.
-    PodArrayZero(phaseStartTimes);
-    PodArrayZero(phaseTimes);
+    PodZero(&phaseStartTimes[PHASE_GC_BEGIN], PHASE_LIMIT - PHASE_GC_BEGIN);
+    PodZero(&phaseTimes[PHASE_GC_BEGIN], PHASE_LIMIT - PHASE_GC_BEGIN);
 }
 
 void
@@ -836,12 +840,50 @@ 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;
@@ -868,6 +910,13 @@ Statistics::endPhase(Phase phase)
         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,
@@ -128,6 +129,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; }
 
@@ -189,6 +193,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];
 
@@ -204,12 +215,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
-    mozilla::DebugOnly<size_t> phaseNestingDepth;
+    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"
 
@@ -99,7 +100,7 @@ StoreBuffer::MonoTypeBuffer<T>::handleOverflow(StoreBuffer *owner)
          * Compact the buffer now, and if that fails to free enough space then
          * trigger a minor collection.
          */
-        gcstats::AutoPhase ap(owner->stats(), PHASE_COMPACT_STOREBUFFER_NO_PARENT);
+        gcstats::AutoPhase ap(owner->stats(), gcstats::PHASE_COMPACT_STOREBUFFER_NO_PARENT);
         owner->stats().count(gcstats::STAT_STOREBUFFER_OVERFLOW);
         compact(owner);
         if (isLowOnSpace())
@@ -111,7 +112,7 @@ StoreBuffer::MonoTypeBuffer<T>::handleOverflow(StoreBuffer *owner)
           */
         if (storage_->availableInCurrentChunk() < sizeof(T)) {
             owner->stats().count(gcstats::STAT_STOREBUFFER_OVERFLOW);
-            maybeCompact(owner, PHASE_COMPACT_STOREBUFFER_NO_PARENT);
+            maybeCompact(owner, gcstats::PHASE_COMPACT_STOREBUFFER_NO_PARENT);
         }
     }
 }
@@ -154,11 +155,11 @@ StoreBuffer::MonoTypeBuffer<T>::compact(StoreBuffer *owner)
 
 template <typename T>
 void
-StoreBuffer::MonoTypeBuffer<T>::maybeCompact(StoreBuffer *owner, gcstats::Phase phase)
+StoreBuffer::MonoTypeBuffer<T>::maybeCompact(StoreBuffer *owner, int phase)
 {
     MOZ_ASSERT(storage_);
     if (storage_->used() != usedAtLastCompact_) {
-        gcstats::AutoPhase ap(owner->stats(), phase);
+        gcstats::AutoPhase ap(owner->stats(), static_cast<gcstats::Phase>(phase));
         compact(owner);
     }
 }
@@ -172,7 +173,7 @@ StoreBuffer::MonoTypeBuffer<T>::mark(StoreBuffer *owner, JSTracer *trc)
     if (!storage_)
         return;
 
-    maybeCompact(owner, PHASE_COMPACT_STOREBUFFER_IN_MINOR_GC);
+    maybeCompact(owner, gcstats::PHASE_COMPACT_STOREBUFFER_IN_MINOR_GC);
 
     for (LifoAlloc::Enum e(*storage_); !e.empty(); e.popFront<T>()) {
         T *edge = e.get<T>();

js/src/gc/StoreBuffer.h

@@ -144,7 +144,7 @@ class StoreBuffer
         virtual void compact(StoreBuffer *owner);
 
         /* Compacts if any entries have been added since the last compaction. */
-        void maybeCompact(StoreBuffer *owner, gcstats::Phase phase);
+        void maybeCompact(StoreBuffer *owner, int phase);
 
         /* Add one item to the buffer. */
         void put(StoreBuffer *owner, const T &t) {

js/src/shell/js.cpp

@@ -1669,6 +1669,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)
 {
@@ -4273,6 +4310,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."),