Bug 1088831 - Account for the storebuffer compaction time, r=jonco
☠☠ backed out by 44ba0c1d88cb ☠ ☠
authorSteve Fink <sfink@mozilla.com>
Thu, 13 Nov 2014 12:23:26 -0800
changeset 215660 dbec0bed9bf5cb2bf6a2e66b41f35e11a6b2615c
parent 215659 bfedb105396ee4713a7d0a7b1b4d0dc85d6f89dc
child 215661 06c511b6093ea188b8675ed73116f3da4fa5797b
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 - 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
@@ -6230,30 +6230,32 @@ GCRuntime::onOutOfMallocMemory(const Aut
     // malloc request.
     decommitAllWithoutUnlocking(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);