Bug 1088831 - Account for the storebuffer compaction time, r=jonco

--HG--
extra : rebase_source : f193ff3774353572c48814f8fd2669d91feb4745

js/src/gc/Statistics.cpp

@@ -326,6 +326,9 @@ static const PhaseInfo phases[] = {
         { PHASE_COMPACT_UPDATE, "Compact Update", PHASE_COMPACT, },
             { PHASE_COMPACT_UPDATE_GRAY, "Compact Update Gray", PHASE_COMPACT_UPDATE, },
     { PHASE_GC_END, "End Callback", PHASE_NO_PARENT },
+    { PHASE_MINOR_GC, "Minor GC", PHASE_NO_PARENT },
+        { PHASE_COMPACT_STOREBUFFER_IN_MINOR_GC, "Compact Store Buffers", PHASE_MINOR_GC },
+    { PHASE_COMPACT_STOREBUFFER_NO_PARENT, "Compact Store Buffers (toplevel)", PHASE_NO_PARENT },
     { PHASE_LIMIT, nullptr, PHASE_NO_PARENT }
 };
 
@@ -386,6 +389,7 @@ Statistics::formatData(StatisticsSerializer &ss, uint64_t timestamp)
     ss.appendNumber("Total Compartments", "%d", "", zoneStats.compartmentCount);
     ss.appendNumber("Minor GCs", "%d", "", counts[STAT_MINOR_GC]);
     ss.appendNumber("Store Buffer Compactions", "%d", "", counts[STAT_COMPACT_STOREBUFFER]);
+    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));
@@ -478,6 +482,7 @@ Statistics::formatDescription()
   Compartments Collected: %d of %d\n\
   MinorGCs since last GC: %d\n\
   Store Buffer Compactions: %d\n\
+  Store Buffer Overflows: %d\n\
   MMU 20ms:%.1f%%; 50ms:%.1f%%\n\
   SCC Sweep Total (MaxPause): %.3fms (%.3fms)\n\
   HeapSize: %.3f MiB\n\
@@ -494,6 +499,7 @@ Statistics::formatDescription()
                 zoneStats.collectedCompartmentCount, zoneStats.compartmentCount,
                 counts[STAT_MINOR_GC],
                 counts[STAT_COMPACT_STOREBUFFER],
+                counts[STAT_STOREBUFFER_OVERFLOW],
                 mmu20 * 100., mmu50 * 100.,
                 t(sccTotal), t(sccLongest),
                 double(preBytes) / 1024. / 1024.,
@@ -643,6 +649,8 @@ Statistics::Statistics(JSRuntime *rt)
 {
     PodArrayZero(phaseTotals);
     PodArrayZero(counts);
+    PodArrayZero(phaseStartTimes);
+    PodArrayZero(phaseTimes);
 
     char *env = getenv("MOZ_GCTIMER");
     if (!env || strcmp(env, "none") == 0) {
@@ -726,9 +734,6 @@ Statistics::printStats()
 void
 Statistics::beginGC(JSGCInvocationKind kind)
 {
-    PodArrayZero(phaseStartTimes);
-    PodArrayZero(phaseTimes);
-
     slices.clearAndFree();
     sccTimes.clearAndFree();
     gckind = kind;
@@ -770,6 +775,11 @@ Statistics::endGC()
 
     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);
 }
 
 void
@@ -837,6 +847,9 @@ Statistics::beginPhase(Phase 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);
+
     phaseNesting[phaseNestingDepth] = phase;
     phaseNestingDepth++;
 #endif
@@ -849,8 +862,10 @@ Statistics::endPhase(Phase phase)
 {
     phaseNestingDepth--;
 
-    int64_t t = PRMJ_Now() - phaseStartTimes[phase];
-    slices.back().phaseTimes[phase] += t;
+    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;
 }

js/src/gc/Statistics.h

@@ -70,6 +70,9 @@ enum Phase {
     PHASE_COMPACT_UPDATE,
     PHASE_COMPACT_UPDATE_GRAY,
     PHASE_GC_END,
+    PHASE_MINOR_GC,
+    PHASE_COMPACT_STOREBUFFER_IN_MINOR_GC,
+    PHASE_COMPACT_STOREBUFFER_NO_PARENT,
 
     PHASE_LIMIT
 };
@@ -78,8 +81,14 @@ enum Stat {
     STAT_NEW_CHUNK,
     STAT_DESTROY_CHUNK,
     STAT_MINOR_GC,
+
+    // Number of times the storebuffers were compacted
     STAT_COMPACT_STOREBUFFER,
 
+    // Number of times a 'put' into a storebuffer overflowed, triggering a
+    // compaction
+    STAT_STOREBUFFER_OVERFLOW,
+
     STAT_LIMIT
 };
 

js/src/gc/StoreBuffer.cpp

@@ -99,6 +99,8 @@ 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);
+        owner->stats().count(gcstats::STAT_STOREBUFFER_OVERFLOW);
         compact(owner);
         if (isLowOnSpace())
             owner->setAboutToOverflow();
@@ -107,8 +109,10 @@ StoreBuffer::MonoTypeBuffer<T>::handleOverflow(StoreBuffer *owner)
           * A minor GC has already been triggered, so there's no point
           * compacting unless the buffer is totally full.
           */
-        if (storage_->availableInCurrentChunk() < sizeof(T))
-            maybeCompact(owner);
+        if (storage_->availableInCurrentChunk() < sizeof(T)) {
+            owner->stats().count(gcstats::STAT_STOREBUFFER_OVERFLOW);
+            maybeCompact(owner, PHASE_COMPACT_STOREBUFFER_NO_PARENT);
+        }
     }
 }
 
@@ -116,8 +120,6 @@ template <typename T>
 void
 StoreBuffer::MonoTypeBuffer<T>::compactRemoveDuplicates(StoreBuffer *owner)
 {
-    Statistics& stats = owner->stats();
-
     typedef HashSet<T, typename T::Hasher, SystemAllocPolicy> DedupSet;
 
     DedupSet duplicates;
@@ -138,7 +140,7 @@ StoreBuffer::MonoTypeBuffer<T>::compactRemoveDuplicates(StoreBuffer *owner)
     storage_->release(insert.mark());
 
     duplicates.clear();
-    stats.count(gcstats::STAT_COMPACT_STOREBUFFER);
+    owner->stats().count(gcstats::STAT_COMPACT_STOREBUFFER);
 }
 
 template <typename T>
@@ -152,11 +154,13 @@ StoreBuffer::MonoTypeBuffer<T>::compact(StoreBuffer *owner)
 
 template <typename T>
 void
-StoreBuffer::MonoTypeBuffer<T>::maybeCompact(StoreBuffer *owner)
+StoreBuffer::MonoTypeBuffer<T>::maybeCompact(StoreBuffer *owner, gcstats::Phase phase)
 {
     MOZ_ASSERT(storage_);
-    if (storage_->used() != usedAtLastCompact_)
+    if (storage_->used() != usedAtLastCompact_) {
+        gcstats::AutoPhase ap(owner->stats(), phase);
         compact(owner);
+    }
 }
 
 template <typename T>
@@ -168,7 +172,8 @@ StoreBuffer::MonoTypeBuffer<T>::mark(StoreBuffer *owner, JSTracer *trc)
     if (!storage_)
         return;
 
-    maybeCompact(owner);
+    maybeCompact(owner, PHASE_COMPACT_STOREBUFFER_IN_MINOR_GC);
+
     for (LifoAlloc::Enum e(*storage_); !e.empty(); e.popFront<T>()) {
         T *edge = e.get<T>();
         edge->mark(trc);

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);
+        void maybeCompact(StoreBuffer *owner, gcstats::Phase phase);
 
         /* Add one item to the buffer. */
         void put(StoreBuffer *owner, const T &t) {

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

@@ -6235,6 +6235,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);
@@ -6249,6 +6250,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);