Bug 1464986 (Part 2) - Add some debug logging to the GC r=jonco

--HG--
extra : rebase_source : fe65d58434aaae63ae2b1d42520a8b1a57247073
extra : histedit_source : b0ad0e6ed49eaca269066599df859d831e7f5dfa

js/src/gc/GC.cpp

@@ -7072,6 +7072,14 @@ GCRuntime::incrementalCollectSlice(SliceBudget& budget, JS::gcreason::Reason rea
     bool useZeal = false;
 #endif
 
+#ifdef DEBUG
+    {
+        char budgetBuffer[32];
+        budget.describe(budgetBuffer, 32);
+        stats().writeLogMessage("Incremental: %d, useZeal: %d, budget: %s",
+            bool(isIncremental), bool(useZeal), budgetBuffer);
+    }
+#endif
     MOZ_ASSERT_IF(isIncrementalGCInProgress(), isIncremental);
     if (isIncrementalGCInProgress() && budget.isUnlimited())
         changeToNonIncrementalGC();
@@ -7083,6 +7091,8 @@ GCRuntime::incrementalCollectSlice(SliceBudget& budget, JS::gcreason::Reason rea
          * Yields between slices occurs at predetermined points in these modes;
          * the budget is not used.
          */
+        stats().writeLogMessage(
+            "Using unlimited budget for two-slice zeal mode");
         budget.makeUnlimited();
     }
 
@@ -7130,7 +7140,7 @@ GCRuntime::incrementalCollectSlice(SliceBudget& budget, JS::gcreason::Reason rea
         MOZ_ASSERT(marker.isDrained());
 
         /*
-         * In incremental GCs where we have already performed more than once
+         * In incremental GCs where we have already performed more than one
          * slice we yield after marking with the aim of starting the sweep in
          * the next slice, since the first slice of sweeping can be expensive.
          *
@@ -7147,6 +7157,7 @@ GCRuntime::incrementalCollectSlice(SliceBudget& budget, JS::gcreason::Reason rea
              (useZeal && hasZealMode(ZealMode::YieldBeforeSweeping))))
         {
             lastMarkSlice = true;
+            stats().writeLogMessage("Yeilding before starting sweeping");
             break;
         }
 
@@ -7622,6 +7633,9 @@ GCRuntime::collect(bool nonincrementalByAPI, SliceBudget budget, JS::gcreason::R
     if (!checkIfGCAllowedInCurrentState(reason))
         return;
 
+    stats().writeLogMessage("GC starting in state %s",
+        StateName(incrementalState));
+
     AutoTraceLog logGC(TraceLoggerForCurrentThread(), TraceLogger_GC);
     AutoStopVerifyingBarriers av(rt, IsShutdownGC(reason));
     AutoEnqueuePendingParseTasksAfterGC aept(*this);
@@ -7633,6 +7647,7 @@ GCRuntime::collect(bool nonincrementalByAPI, SliceBudget budget, JS::gcreason::R
 
         if (reason == JS::gcreason::ABORT_GC) {
             MOZ_ASSERT(!isIncrementalGCInProgress());
+            stats().writeLogMessage("GC aborted by request");
             break;
         }
 
@@ -7672,6 +7687,7 @@ GCRuntime::collect(bool nonincrementalByAPI, SliceBudget budget, JS::gcreason::R
         MOZ_RELEASE_ASSERT(CheckGrayMarkingState(rt));
     }
 #endif
+    stats().writeLogMessage("GC ending");
 }
 
 js::AutoEnqueuePendingParseTasksAfterGC::~AutoEnqueuePendingParseTasksAfterGC()

js/src/gc/Statistics.cpp

@@ -97,6 +97,30 @@ js::gcstats::ExplainAbortReason(gc::AbortReason reason)
     }
 }
 
+static FILE*
+MaybeOpenFileFromEnv(const char* env)
+{
+    FILE *file;
+    const char* value = getenv(env);
+
+    if (!value)
+        return nullptr;
+
+    if (strcmp(value, "none") == 0) {
+        file = nullptr;
+    } else if (strcmp(value, "stdout") == 0) {
+        file = stdout;
+    } else if (strcmp(value, "stderr") == 0) {
+        file = stderr;
+    } else {
+        file = fopen(value, "a");
+        if (!file)
+            MOZ_CRASH("Failed to open log file.");
+    }
+
+    return file;
+}
+
 struct PhaseKindInfo
 {
     Phase firstPhase;
@@ -551,6 +575,24 @@ Statistics::renderNurseryJson(JSRuntime* rt) const
     return UniqueChars(printer.release());
 }
 
+#ifdef DEBUG
+void
+Statistics::writeLogMessage(const char* fmt, ...)
+{
+    va_list args;
+    va_start(args, fmt);
+    if (gcDebugFile) {
+        TimeDuration sinceStart = TimeStamp::Now() -
+            TimeStamp::ProcessCreation();
+        fprintf(gcDebugFile, "%12.3f: ", sinceStart.ToMicroseconds());
+        vfprintf(gcDebugFile, fmt, args);
+        fprintf(gcDebugFile, "\n");
+        fflush(gcDebugFile);
+    }
+    va_end(args);
+}
+#endif
+
 UniqueChars
 Statistics::renderJsonMessage(uint64_t timestamp, bool includeSlices) const
 {
@@ -696,6 +738,7 @@ Statistics::formatJsonPhaseTimes(const PhaseTimeTable& phaseTimes, JSONPrinter&
 Statistics::Statistics(JSRuntime* rt)
   : runtime(rt),
     gcTimerFile(nullptr),
+    gcDebugFile(nullptr),
     nonincrementalReason_(gc::AbortReason::None),
     preBytes(0),
     thresholdTriggered(false),
@@ -734,22 +777,10 @@ Statistics::Statistics(JSRuntime* rt)
     MOZ_ALWAYS_TRUE(phaseStack.reserve(MAX_PHASE_NESTING));
     MOZ_ALWAYS_TRUE(suspendedPhases.reserve(MAX_SUSPENDED_PHASES));
 
-    const char* env = getenv("MOZ_GCTIMER");
-    if (env) {
-        if (strcmp(env, "none") == 0) {
-            gcTimerFile = nullptr;
-        } else if (strcmp(env, "stdout") == 0) {
-            gcTimerFile = stdout;
-        } else if (strcmp(env, "stderr") == 0) {
-            gcTimerFile = stderr;
-        } else {
-            gcTimerFile = fopen(env, "a");
-            if (!gcTimerFile)
-                MOZ_CRASH("Failed to open MOZ_GCTIMER log file.");
-        }
-    }
+    gcTimerFile = MaybeOpenFileFromEnv("MOZ_GCTIMER");
+    gcDebugFile = MaybeOpenFileFromEnv("JS_GC_DEBUG");
 
-    env = getenv("JS_GC_PROFILE");
+    const char* env = getenv("JS_GC_PROFILE");
     if (env) {
         if (0 == strcmp(env, "help")) {
             fprintf(stderr, "JS_GC_PROFILE=N\n"
@@ -765,6 +796,8 @@ Statistics::~Statistics()
 {
     if (gcTimerFile && gcTimerFile != stdout && gcTimerFile != stderr)
         fclose(gcTimerFile);
+    if (gcDebugFile && gcDebugFile != stdout && gcDebugFile != stderr)
+        fclose(gcDebugFile);
 }
 
 /* static */ bool
@@ -1035,6 +1068,8 @@ Statistics::beginSlice(const ZoneGCStats& zoneStats, JSGCInvocationKind gckind,
             (*sliceCallback)(cx, JS::GC_CYCLE_BEGIN, desc);
         (*sliceCallback)(cx, JS::GC_SLICE_BEGIN, desc);
     }
+
+    writeLogMessage("begin slice");
 }
 
 void
@@ -1049,6 +1084,7 @@ Statistics::endSlice()
         slice.endFaults = GetPageFaultCount();
         slice.finalState = runtime->gc.state();
 
+        writeLogMessage("end slice");
         TimeDuration sliceTime = slice.end - slice.start;
         runtime->addTelemetry(JS_TELEMETRY_GC_SLICE_MS, t(sliceTime));
         runtime->addTelemetry(JS_TELEMETRY_GC_RESET, slice.wasReset());
@@ -1250,6 +1286,7 @@ Statistics::recordPhaseBegin(Phase phase)
 
     phaseStack.infallibleAppend(phase);
     phaseStartTimes[phase] = now;
+    writeLogMessage("begin: %s", phases[phase].path);
 }
 
 void
@@ -1299,6 +1336,7 @@ Statistics::recordPhaseEnd(Phase phase)
 
 #ifdef DEBUG
     phaseEndTimes[phase] = now;
+    writeLogMessage("end: %s", phases[phase].path);
 #endif
 }
 

js/src/gc/Statistics.h

@@ -166,6 +166,8 @@ struct Statistics
     void nonincremental(gc::AbortReason reason) {
         MOZ_ASSERT(reason != gc::AbortReason::None);
         nonincrementalReason_ = reason;
+        writeLogMessage("Non-incremental reason: %s",
+            nonincrementalReason());
     }
 
     bool nonincremental() const {
@@ -266,12 +268,22 @@ struct Statistics
     // Return JSON for the previous nursery collection.
     UniqueChars renderNurseryJson(JSRuntime* rt) const;
 
+#ifdef DEBUG
+    // Print a logging message.
+    void writeLogMessage(const char* fmt, ...);
+#else
+    void writeLogMessage(const char* fmt, ...) { };
+#endif
+
   private:
     JSRuntime* runtime;
 
     /* File used for MOZ_GCTIMER output. */
     FILE* gcTimerFile;
 
+    /* File used for JS_GC_DEBUG output. */
+    FILE* gcDebugFile;
+
     ZoneGCStats zoneStats;
 
     JSGCInvocationKind gckind;