Bug 1088831 - Track mutator vs GC time in specified intervals, r=jonco
☠☠ backed out by 44ba0c1d88cb ☠ ☠
authorSteve Fink <sfink@mozilla.com>
Thu, 13 Nov 2014 12:23:26 -0800
changeset 215661 06c511b6093ea188b8675ed73116f3da4fa5797b
parent 215660 dbec0bed9bf5cb2bf6a2e66b41f35e11a6b2615c
child 215662 b322b316e6f26aa2ceb1cbb3e08da0858682dc29
push id51816
push usersfink@mozilla.com
push dateFri, 14 Nov 2014 00:18:34 +0000
treeherdermozilla-inbound@06c511b6093e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjonco
bugs1088831
milestone36.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 1088831 - Track mutator vs GC time in specified intervals, r=jonco
js/src/gc/Statistics.cpp
js/src/gc/Statistics.h
js/src/gc/StoreBuffer.cpp
js/src/gc/StoreBuffer.h
js/src/shell/js.cpp
--- a/js/src/gc/Statistics.cpp
+++ b/js/src/gc/Statistics.cpp
@@ -22,16 +22,17 @@
 #include "vm/HelperThreads.h"
 #include "vm/Runtime.h"
 
 using namespace js;
 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;
 
 class gcstats::StatisticsSerializer
 {
     typedef Vector<char, 128, SystemAllocPolicy> CharBuffer;
     CharBuffer buf_;
@@ -278,16 +279,17 @@ struct PhaseInfo
     Phase index;
     const char *name;
     Phase parent;
 };
 
 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 },
     { PHASE_PURGE, "Purge", PHASE_NO_PARENT },
     { PHASE_MARK, "Mark", PHASE_NO_PARENT },
         { PHASE_MARK_ROOTS, "Mark Roots", PHASE_MARK },
         { PHASE_MARK_DELAYED, "Mark Delayed", PHASE_MARK },
     { PHASE_SWEEP, "Sweep", PHASE_NO_PARENT },
@@ -637,16 +639,18 @@ 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),
     sliceCallback(nullptr)
 {
     PodArrayZero(phaseTotals);
     PodArrayZero(counts);
     PodArrayZero(phaseStartTimes);
@@ -773,18 +777,18 @@ Statistics::endGC()
         (*cb)(JS_TELEMETRY_GC_MMU_50, mmu50 * 100);
     }
 
     if (fp)
         printStats();
 
     // 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
 Statistics::beginSlice(const ZoneGCStats &zoneStats, JSGCInvocationKind gckind,
                        JS::gcreason::Reason reason)
 {
     this->zoneStats = zoneStats;
 
@@ -832,21 +836,59 @@ 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);
+
+    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);
     MOZ_ASSERT_IF(phase == PHASE_COMPACT_STOREBUFFER_IN_MINOR_GC, parent == PHASE_MINOR_GC);
     MOZ_ASSERT_IF(phase == PHASE_COMPACT_STOREBUFFER_NO_PARENT, parent == PHASE_NO_PARENT);
 
@@ -863,16 +905,23 @@ Statistics::endPhase(Phase phase)
     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) {
+            timedGCTime += now - timedGCStart;
+            beginPhase(PHASE_MUTATOR);
+        }
+    }
 }
 
 void
 Statistics::endParallelPhase(Phase phase, const GCParallelTask *task)
 {
     phaseNestingDepth--;
 
     slices.back().phaseTimes[phase] += task->duration();
--- a/js/src/gc/Statistics.h
+++ b/js/src/gc/Statistics.h
@@ -22,16 +22,17 @@ struct JSCompartment;
 
 namespace js {
 
 class GCParallelTask;
 
 namespace gcstats {
 
 enum Phase {
+    PHASE_MUTATOR,
     PHASE_GC_BEGIN,
     PHASE_WAIT_BACKGROUND_THREAD,
     PHASE_MARK_DISCARD_CODE,
     PHASE_PURGE,
     PHASE_MARK,
     PHASE_MARK_ROOTS,
     PHASE_MARK_DELAYED,
     PHASE_SWEEP,
@@ -123,16 +124,19 @@ struct Statistics
     void beginPhase(Phase phase);
     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);
+
     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]++;
     }
 
@@ -184,37 +188,42 @@ 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. */
     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;
 
     /* 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::GCSliceCallback sliceCallback;
 
     void beginGC(JSGCInvocationKind kind);
     void endGC();
--- a/js/src/gc/StoreBuffer.cpp
+++ b/js/src/gc/StoreBuffer.cpp
@@ -5,16 +5,17 @@
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #ifdef JSGC_GENERATIONAL
 
 #include "gc/StoreBuffer.h"
 
 #include "mozilla/Assertions.h"
 
+#include "gc/Statistics.h"
 #include "vm/ArgumentsObject.h"
 #include "vm/ForkJoin.h"
 
 #include "jsgcinlines.h"
 
 using namespace js;
 using namespace js::gc;
 using mozilla::ReentrancyGuard;
@@ -94,29 +95,29 @@ template <typename T>
 void
 StoreBuffer::MonoTypeBuffer<T>::handleOverflow(StoreBuffer *owner)
 {
     if (!owner->isAboutToOverflow()) {
         /*
          * 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())
             owner->setAboutToOverflow();
     } else {
          /*
           * A minor GC has already been triggered, so there's no point
           * compacting unless the buffer is totally full.
           */
         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);
         }
     }
 }
 
 template <typename T>
 void
 StoreBuffer::MonoTypeBuffer<T>::compactRemoveDuplicates(StoreBuffer *owner)
 {
@@ -149,35 +150,35 @@ StoreBuffer::MonoTypeBuffer<T>::compact(
 {
     MOZ_ASSERT(storage_);
     compactRemoveDuplicates(owner);
     usedAtLastCompact_ = storage_->used();
 }
 
 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);
     }
 }
 
 template <typename T>
 void
 StoreBuffer::MonoTypeBuffer<T>::mark(StoreBuffer *owner, JSTracer *trc)
 {
     MOZ_ASSERT(owner->isEnabled());
     ReentrancyGuard g(*owner);
     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>();
         edge->mark(trc);
     }
 }
 
 /*** RelocatableMonoTypeBuffer ***/
--- a/js/src/gc/StoreBuffer.h
+++ b/js/src/gc/StoreBuffer.h
@@ -139,17 +139,17 @@ class StoreBuffer
 
         /*
          * Attempts to reduce the usage of the buffer by removing unnecessary
          * entries.
          */
         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) {
             MOZ_ASSERT(storage_);
 
             T *tp = storage_->new_<T>(t);
             if (!tp)
                 CrashAtUnhandlableOOM("Failed to allocate for MonoTypeBuffer::put.");
--- a/js/src/shell/js.cpp
+++ b/js/src/shell/js.cpp
@@ -1664,16 +1664,53 @@ Quit(JSContext *cx, unsigned argc, jsval
 
     CallArgs args = CallArgsFromVp(argc, vp);
     JS_ConvertArguments(cx, args, "/ i", &gExitCode);
 
     gQuitting = true;
     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)
 {
     JSString *str = JS_ValueToSource(cx, vp);
     if (str) {
         vp.setString(str);
         if (bytes->encodeLatin1(cx, str))
             return bytes->ptr();
@@ -4268,16 +4305,24 @@ static const JSFunctionSpecWithHelp shel
 "quit()",
 "  Quit the shell."),
 
     JS_FN_HELP("assertEq", AssertEq, 2, 0,
 "assertEq(actual, expected[, msg])",
 "  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."),
 
 #ifdef DEBUG
     JS_FN_HELP("disassemble", DisassembleToString, 1, 0,
 "disassemble([fun])",
 "  Return the disassembly for the given function."),