Bug 1088831 - Account for the storebuffer compaction time, r=jonco
☠☠ backed out by 3439514abf7b ☠ ☠
authorSteve Fink <sfink@mozilla.com>
Mon, 03 Nov 2014 14:15:37 -0800
changeset 213789 15e064492127ba86c5eb7e6ec5e42bbda422fbf0
parent 213788 70a7f15c30fb4b3face1ec3dcce2fd025a95c8c4
child 213790 5156cefdad51ca3d0d56cf8cfb4895864e85ce84
push id51327
push usersfink@mozilla.com
push dateTue, 04 Nov 2014 02:39:57 +0000
treeherdermozilla-inbound@5156cefdad51 [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/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/jsgc.cpp
+++ b/js/src/jsgc.cpp
@@ -6196,30 +6196,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);