Bug 962576 - Add option to time minor collections and dump the results r=terrence

js/src/gc/Nursery.cpp

@@ -9,10 +9,13 @@
 
 #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"
@@ -32,6 +35,15 @@ 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()
 {
@@ -68,6 +80,12 @@ js::Nursery::init()
     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;
 }
@@ -626,6 +644,16 @@ CheckHashTablesAfterMovingGC(JSRuntime *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)
 {
@@ -640,17 +668,36 @@ js::Nursery::collect(JSRuntime *rt, JS::gcreason::Reason reason, TypeObjectList
     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
@@ -658,21 +705,28 @@ js::Nursery::collect(JSRuntime *rt, JS::gcreason::Reason reason, TypeObjectList
      * 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
@@ -684,10 +738,13 @@ js::Nursery::collect(JSRuntime *rt, JS::gcreason::Reason reason, TypeObjectList
                 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
@@ -696,6 +753,37 @@ js::Nursery::collect(JSRuntime *rt, JS::gcreason::Reason reason, TypeObjectList
      */
     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