From a05872f75b01700f0dff0ae011adc47e064902e0 Mon Sep 17 00:00:00 2001 From: Paul Bone Date: Wed, 30 May 2018 22:50:46 +1000 Subject: [PATCH] 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 | 18 ++++++++++- js/src/gc/Statistics.cpp | 68 +++++++++++++++++++++++++++++++--------- js/src/gc/Statistics.h | 12 +++++++ 3 files changed, 82 insertions(+), 16 deletions(-) diff --git a/js/src/gc/GC.cpp b/js/src/gc/GC.cpp index da08684843b2..2172f2721752 100644 --- a/js/src/gc/GC.cpp +++ b/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() diff --git a/js/src/gc/Statistics.cpp b/js/src/gc/Statistics.cpp index 0f5e6c8610ba..bb8a9501fdd7 100644 --- a/js/src/gc/Statistics.cpp +++ b/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 } diff --git a/js/src/gc/Statistics.h b/js/src/gc/Statistics.h index de26dbafa95c..23ddefc5e9f6 100644 --- a/js/src/gc/Statistics.h +++ b/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;