Bug 1088831 - Account for the storebuffer compaction time, r=jonco
authorSteve Fink <sfink@mozilla.com>
Tue, 04 Nov 2014 13:23:10 -0800
changeset 213917 d6aceb31282a45692389874e0c1d3678f140da60
parent 213916 7a9f3b3b30068a6bc78ce1d25dc14af2a79ba90c
child 213918 5cbe9fc3c2ff56c4032d7afdee8f3029e73a6c15
push id51374
push usersfink@mozilla.com
push dateTue, 04 Nov 2014 21:28:18 +0000
treeherdermozilla-inbound@5cbe9fc3c2ff [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 - Account for the storebuffer compaction time, r=jonco
js/src/gc/Statistics.cpp
js/src/gc/Statistics.h
js/src/gc/StoreBuffer.cpp
js/src/gc/StoreBuffer.h
js/src/gc/Verifier.cpp
js/src/jsgc.cpp
--- a/js/src/gc/Statistics.cpp
+++ b/js/src/gc/Statistics.cpp
@@ -321,16 +321,19 @@ static const PhaseInfo phases[] = {
         { PHASE_SWEEP_JITCODE, "Sweep JIT code", PHASE_SWEEP },
         { PHASE_FINALIZE_END, "Finalize End Callback", PHASE_SWEEP },
         { PHASE_DESTROY, "Deallocate", PHASE_SWEEP },
     { PHASE_COMPACT, "Compact", PHASE_NO_PARENT },
         { PHASE_COMPACT_MOVE, "Compact Move", PHASE_COMPACT },
         { 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 }
 };
 
 static void
 FormatPhaseTimes(StatisticsSerializer &ss, const char *name, int64_t *times)
 {
     ss.beginObject(name);
     for (unsigned i = 0; phases[i].name; i++)
@@ -381,16 +384,17 @@ Statistics::formatData(StatisticsSeriali
     else
         ss.appendString("Reason", ExplainReason(slices[0].reason));
     ss.appendDecimal("Total Time", "ms", t(total));
     ss.appendNumber("Zones Collected", "%d", "", zoneStats.collectedZoneCount);
     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 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));
     ss.appendDecimal("SCC Sweep Max Pause", "ms", t(sccLongest));
     if (nonincrementalReason || ss.isJSON()) {
         ss.appendString("Nonincremental Reason",
                         nonincrementalReason ? nonincrementalReason : "none");
     }
@@ -473,32 +477,34 @@ Statistics::formatDescription()
 "=================================================================\n\
   Invocation Kind: %s\n\
   Reason: %s\n\
   Incremental: %s%s\n\
   Zones Collected: %d of %d\n\
   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\
   Chunk Delta (magnitude): %+d  (%d)\n\
 ";
     char buffer[1024];
     memset(buffer, 0, sizeof(buffer));
     JS_snprintf(buffer, sizeof(buffer), format,
                 ExplainInvocationKind(gckind),
                 ExplainReason(slices[0].reason),
                 nonincrementalReason ? "no - " : "yes",
                                                   nonincrementalReason ? nonincrementalReason : "",
                 zoneStats.collectedZoneCount, zoneStats.zoneCount,
                 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.,
                 counts[STAT_NEW_CHUNK] - counts[STAT_DESTROY_CHUNK], counts[STAT_NEW_CHUNK] +
                                                                   counts[STAT_DESTROY_CHUNK]);
     return make_string_copy(buffer);
 }
 
@@ -638,16 +644,18 @@ Statistics::Statistics(JSRuntime *rt)
     nonincrementalReason(nullptr),
     preBytes(0),
     maxPauseInInterval(0),
     phaseNestingDepth(0),
     sliceCallback(nullptr)
 {
     PodArrayZero(phaseTotals);
     PodArrayZero(counts);
+    PodArrayZero(phaseStartTimes);
+    PodArrayZero(phaseTimes);
 
     char *env = getenv("MOZ_GCTIMER");
     if (!env || strcmp(env, "none") == 0) {
         fp = nullptr;
         return;
     }
 
     if (strcmp(env, "stdout") == 0) {
@@ -721,19 +729,16 @@ Statistics::printStats()
                 t(phaseTimes[PHASE_SWEEP]));
     }
     fflush(fp);
 }
 
 void
 Statistics::beginGC(JSGCInvocationKind kind)
 {
-    PodArrayZero(phaseStartTimes);
-    PodArrayZero(phaseTimes);
-
     slices.clearAndFree();
     sccTimes.clearAndFree();
     gckind = kind;
     nonincrementalReason = nullptr;
 
     preBytes = runtime->gc.usage.gcBytes();
 }
 
@@ -765,16 +770,21 @@ Statistics::endGC()
         (*cb)(JS_TELEMETRY_GC_SCC_SWEEP_MAX_PAUSE_MS, t(sccLongest));
 
         double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
         (*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);
 }
 
 void
 Statistics::beginSlice(const ZoneGCStats &zoneStats, JSGCInvocationKind gckind,
                        JS::gcreason::Reason reason)
 {
     this->zoneStats = zoneStats;
 
@@ -832,30 +842,35 @@ Statistics::beginPhase(Phase phase)
     /* Guard against 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);
     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
 
     phaseStartTimes[phase] = PRMJ_Now();
 }
 
 void
 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;
 }
 
 void
 Statistics::endParallelPhase(Phase phase, const GCParallelTask *task)
 {
     phaseNestingDepth--;
--- a/js/src/gc/Statistics.h
+++ b/js/src/gc/Statistics.h
@@ -65,26 +65,35 @@ enum Phase {
     PHASE_SWEEP_JITCODE,
     PHASE_FINALIZE_END,
     PHASE_DESTROY,
     PHASE_COMPACT,
     PHASE_COMPACT_MOVE,
     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
 };
 
 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
 };
 
 class StatisticsSerializer;
 
 struct ZoneGCStats
 {
     /* Number of zones collected in this GC. */
--- a/js/src/gc/StoreBuffer.cpp
+++ b/js/src/gc/StoreBuffer.cpp
@@ -94,35 +94,37 @@ 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);
+        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))
-            maybeCompact(owner);
+        if (storage_->availableInCurrentChunk() < sizeof(T)) {
+            owner->stats().count(gcstats::STAT_STOREBUFFER_OVERFLOW);
+            maybeCompact(owner, PHASE_COMPACT_STOREBUFFER_NO_PARENT);
+        }
     }
 }
 
 template <typename T>
 void
 StoreBuffer::MonoTypeBuffer<T>::compactRemoveDuplicates(StoreBuffer *owner)
 {
-    Statistics& stats = owner->stats();
-
     typedef HashSet<T, typename T::Hasher, SystemAllocPolicy> DedupSet;
 
     DedupSet duplicates;
     if (!duplicates.init())
         return; /* Failure to de-dup is acceptable. */
 
     LifoAlloc::Enum insert(*storage_);
     for (LifoAlloc::Enum e(*storage_); !e.empty(); e.popFront<T>()) {
@@ -133,47 +135,50 @@ StoreBuffer::MonoTypeBuffer<T>::compactR
 
             /* Failure to insert will leave the set with duplicates. Oh well. */
             duplicates.put(*edge);
         }
     }
     storage_->release(insert.mark());
 
     duplicates.clear();
-    stats.count(gcstats::STAT_COMPACT_STOREBUFFER);
+    owner->stats().count(gcstats::STAT_COMPACT_STOREBUFFER);
 }
 
 template <typename T>
 void
 StoreBuffer::MonoTypeBuffer<T>::compact(StoreBuffer *owner)
 {
     MOZ_ASSERT(storage_);
     compactRemoveDuplicates(owner);
     usedAtLastCompact_ = storage_->used();
 }
 
 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>
 void
 StoreBuffer::MonoTypeBuffer<T>::mark(StoreBuffer *owner, JSTracer *trc)
 {
     MOZ_ASSERT(owner->isEnabled());
     ReentrancyGuard g(*owner);
     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);
     }
 }
 
 /*** 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);
+        void maybeCompact(StoreBuffer *owner, gcstats::Phase 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/gc/Verifier.cpp
+++ b/js/src/gc/Verifier.cpp
@@ -498,17 +498,20 @@ js::gc::GCRuntime::endVerifyPostBarriers
     VerifyPostTracer::EdgeSet edges;
     AutoPrepareForTracing prep(rt, SkipAtoms);
 
     /* Visit every entry in the store buffer and put the edges in a hash set. */
     trc->setTraceCallback(PostVerifierCollectStoreBufferEdges);
     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);
     for (GCZoneGroupIter zone(rt); !zone.done(); zone.next()) {
         for (size_t kind = 0; kind < FINALIZE_LIMIT; ++kind) {
             for (ZoneCellIterUnderGC cells(zone, AllocKind(kind)); !cells.done(); cells.next()) {
                 Cell *src = cells.getCell();
                 JS_TraceChildren(trc, src, MapAllocToTraceKind(AllocKind(kind)));
--- a/js/src/jsgc.cpp
+++ b/js/src/jsgc.cpp
@@ -6212,30 +6212,32 @@ GCRuntime::shrinkBuffers()
     else
         expireChunksAndArenas(true, lock);
 }
 
 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);
     nursery.collect(rt, reason, nullptr);
     MOZ_ASSERT_IF(!rt->mainThread.suppressGC, nursery.isEmpty());
 #endif
 }
 
 void
 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);
     Nursery::TypeObjectList pretenureTypes;
     nursery.collect(rt, reason, &pretenureTypes);
     for (size_t i = 0; i < pretenureTypes.length(); i++) {
         if (pretenureTypes[i]->canPreTenure())
             pretenureTypes[i]->setShouldPreTenure(cx);