Bug 962576 - Add option to time minor collections and dump the results r=terrence
authorJon Coppeard <jcoppeard@mozilla.com>
Thu, 23 Jan 2014 09:53:42 +0000
changeset 164792 e6197abbed3ab7da83018816159a3fda2736c690
parent 164791 00b51ce701ff71d9190d839927352cd505c6b8d6
child 164835 7fdda1995af8ff9196c8393a46c02efbc6acf175
push id38816
push userjcoppeard@mozilla.com
push dateThu, 23 Jan 2014 10:04:31 +0000
treeherdermozilla-inbound@e6197abbed3a [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersterrence
bugs962576
milestone29.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 962576 - Add option to time minor collections and dump the results r=terrence
js/src/gc/Nursery.cpp
--- a/js/src/gc/Nursery.cpp
+++ b/js/src/gc/Nursery.cpp
@@ -4,20 +4,23 @@
  * This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this file,
  * You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #ifdef JSGC_GENERATIONAL
 
 #include "gc/Nursery-inl.h"
 
+#include <inttypes.h>
+
 #include "jscompartment.h"
 #include "jsgc.h"
 #include "jsinfer.h"
 #include "jsutil.h"
+#include "prmjtime.h"
 
 #include "gc/GCInternals.h"
 #include "gc/Memory.h"
 #ifdef JS_ION
 #include "jit/IonFrames.h"
 #endif
 #include "vm/ArrayObject.h"
 #include "vm/Debugger.h"
@@ -27,16 +30,25 @@
 #include "vm/TypedArrayObject.h"
 
 #include "jsgcinlines.h"
 
 using namespace js;
 using namespace gc;
 using namespace mozilla;
 
+//#define PROFILE_NURSERY
+
+#ifdef PROFILE_NURSERY
+/*
+ * Print timing information for minor GCs that take longer than this time in microseconds.
+ */
+static int64_t GCReportThreshold = INT64_MAX;
+#endif
+
 bool
 js::Nursery::init()
 {
     JS_ASSERT(start() == 0);
 
     if (!hugeSlots.init())
         return false;
 
@@ -63,16 +75,22 @@ js::Nursery::init()
     numActiveChunks_ = 1;
     setCurrentChunk(0);
 #ifdef JS_GC_ZEAL
     JS_POISON(heap, FreshNursery, NurserySize);
 #endif
     for (int i = 0; i < NumNurseryChunks; ++i)
         chunk(i).trailer.runtime = rt;
 
+#ifdef PROFILE_NURSERY
+    char *env = getenv("JS_MINORGC_TIME");
+    if (env)
+        GCReportThreshold = atoi(env);
+#endif
+
     JS_ASSERT(isEnabled());
     return true;
 }
 
 js::Nursery::~Nursery()
 {
     if (start())
         UnmapPages(runtime(), (void *)start(), NurserySize);
@@ -621,86 +639,156 @@ CheckHashTablesAfterMovingGC(JSRuntime *
             c->checkWrapperMapAfterMovingGC();
             if (c->debugScopes)
                 c->debugScopes->checkHashTablesAfterMovingGC(rt);
         }
     }
 #endif
 }
 
+#ifdef PROFILE_NURSERY
+#define TIME_START(name) int64_t timstampStart_##name = PRMJ_Now()
+#define TIME_END(name) int64_t timstampEnd_##name = PRMJ_Now()
+#define TIME_TOTAL(name) (timstampEnd_##name - timstampStart_##name)
+#else
+#define TIME_START(name)
+#define TIME_END(name)
+#define TIME_TOTAL(name)
+#endif
+
 void
 js::Nursery::collect(JSRuntime *rt, JS::gcreason::Reason reason, TypeObjectList *pretenureTypes)
 {
     JS_AbortIfWrongThread(rt);
 
     if (rt->mainThread.suppressGC)
         return;
 
     if (!isEnabled())
         return;
 
     if (isEmpty())
         return;
 
+    TIME_START(total);
+
     AutoStopVerifyingBarriers av(rt, false);
 
+    TIME_START(waitBgSweep);
     rt->gcHelperThread.waitBackgroundSweepEnd();
+    TIME_END(waitBgSweep);
 
     /* Move objects pointed to by roots from the nursery to the major heap. */
     MinorCollectionTracer trc(rt, this);
+
+    TIME_START(markStoreBuffer);
     rt->gcStoreBuffer.mark(&trc); // This must happen first.
+    TIME_END(markStoreBuffer);
+
+    TIME_START(checkHashTables);
     CheckHashTablesAfterMovingGC(rt);
+    TIME_END(checkHashTables);
+
+    TIME_START(markRuntime);
     MarkRuntime(&trc);
+    TIME_END(markRuntime);
+
+    TIME_START(markDebugger);
     Debugger::markAll(&trc);
+    TIME_END(markDebugger);
+
+    TIME_START(clearNewObjectCache);
     rt->newObjectCache.clearNurseryObjects(rt);
+    TIME_END(clearNewObjectCache);
 
     /*
      * Most of the work is done here. This loop iterates over objects that have
      * been moved to the major heap. If these objects have any outgoing pointers
      * to the nursery, then those nursery objects get moved as well, until no
      * objects are left to move. That is, we iterate to a fixed point.
      */
+    TIME_START(collectToFP);
     TenureCountCache tenureCounts;
     collectToFixedPoint(&trc, tenureCounts);
+    TIME_END(collectToFP);
 
+    TIME_START(updateJitActivations);
 #ifdef JS_ION
     /* Update any slot or element pointers whose destination has been tenured. */
     js::jit::UpdateJitActivationsForMinorGC(rt, &trc);
 #endif
+    TIME_END(updateJitActivations);
 
     /* Resize the nursery. */
+    TIME_START(resize);
     double promotionRate = trc.tenuredSize / double(allocationEnd() - start());
     if (promotionRate > 0.05)
         growAllocableSpace();
     else if (promotionRate < 0.01)
         shrinkAllocableSpace();
+    TIME_END(resize);
 
+    TIME_START(pretenure);
     // If we are promoting the nursery, or exhausted the store buffer with
     // pointers to nursery things, which will force a collection well before
     // the nursery is full, look for object types that are getting promoted
     // excessively and try to pretenure them.
     if (pretenureTypes && (promotionRate > 0.8 || reason == JS::gcreason::FULL_STORE_BUFFER)) {
         for (size_t i = 0; i < ArrayLength(tenureCounts.entries); i++) {
             const TenureCount &entry = tenureCounts.entries[i];
             if (entry.count >= 3000)
                 pretenureTypes->append(entry.type); // ignore alloc failure
         }
     }
+    TIME_END(pretenure);
 
     /* Sweep. */
+    TIME_START(sweep);
     sweep(rt);
     rt->gcStoreBuffer.clear();
+    TIME_END(sweep);
 
     /*
      * We ignore gcMaxBytes when allocating for minor collection. However, if we
      * overflowed, we disable the nursery. The next time we allocate, we'll fail
      * because gcBytes >= gcMaxBytes.
      */
     if (rt->gcBytes >= rt->gcMaxBytes)
         disable();
+
+    TIME_END(total);
+
+#ifdef PROFILE_NURSERY
+    uint64_t totalTime = TIME_TOTAL(total);
+
+    if (totalTime >= GCReportThreshold) {
+        static bool printedHeader = false;
+        if (!printedHeader) {
+            fprintf(stderr,
+                    "MinorGC time: Total   WaitBg  mkStrBf ckHshTb mkRuntm mkDbggr clrNOC  collect updtIon resize  pretnur sweep\n");
+            printedHeader = true;
+        }
+
+#define FMT " %7" PRIu64
+        fprintf(stderr, "MinorGC time:" FMT FMT FMT FMT FMT FMT FMT FMT FMT FMT FMT FMT "\n",
+                totalTime,
+                TIME_TOTAL(waitBgSweep),
+                TIME_TOTAL(markStoreBuffer),
+                TIME_TOTAL(checkHashTables),
+                TIME_TOTAL(markRuntime),
+                TIME_TOTAL(markDebugger),
+                TIME_TOTAL(clearNewObjectCache),
+                TIME_TOTAL(collectToFP),
+                TIME_TOTAL(updateJitActivations),
+                TIME_TOTAL(resize),
+                TIME_TOTAL(pretenure),
+                TIME_TOTAL(sweep));
+#undef FMT
+    }
+#endif
 }
 
 void
 js::Nursery::sweep(JSRuntime *rt)
 {
     /* Free malloced pointers owned by freed things in the nursery. */
     for (HugeSlotsSet::Range r = hugeSlots.all(); !r.empty(); r.popFront())
         rt->defaultFreeOp()->free_(r.front());