summaryrefslogtreecommitdiffstats
path: root/js/src/gc/Statistics.cpp
diff options
context:
space:
mode:
Diffstat (limited to 'js/src/gc/Statistics.cpp')
-rw-r--r--js/src/gc/Statistics.cpp1811
1 files changed, 1811 insertions, 0 deletions
diff --git a/js/src/gc/Statistics.cpp b/js/src/gc/Statistics.cpp
new file mode 100644
index 0000000000..66b1c40673
--- /dev/null
+++ b/js/src/gc/Statistics.cpp
@@ -0,0 +1,1811 @@
+/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*-
+ * vim: set ts=8 sts=2 et sw=2 tw=80:
+ * 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/. */
+
+#include "gc/Statistics.h"
+
+#include "mozilla/DebugOnly.h"
+#include "mozilla/Sprintf.h"
+#include "mozilla/TimeStamp.h"
+
+#include <algorithm>
+#include <stdarg.h>
+#include <stdio.h>
+#include <type_traits>
+
+#include "gc/GC.h"
+#include "gc/GCInternals.h"
+#include "gc/Memory.h"
+#include "js/Printer.h"
+#include "util/GetPidProvider.h"
+#include "util/Text.h"
+#include "vm/JSONPrinter.h"
+#include "vm/Runtime.h"
+#include "vm/Time.h"
+
+#include "gc/PrivateIterators-inl.h"
+
+using namespace js;
+using namespace js::gc;
+using namespace js::gcstats;
+
+using mozilla::DebugOnly;
+using mozilla::EnumeratedArray;
+using mozilla::Maybe;
+using mozilla::TimeDuration;
+using mozilla::TimeStamp;
+
+static const size_t BYTES_PER_MB = 1024 * 1024;
+
+/*
+ * If this fails, then you can either delete this assertion and allow all
+ * larger-numbered reasons to pile up in the last telemetry bucket, or switch
+ * to GC_REASON_3 and bump the max value.
+ */
+static_assert(JS::GCReason::NUM_TELEMETRY_REASONS >= JS::GCReason::NUM_REASONS);
+
+static inline auto AllPhaseKinds() {
+ return mozilla::MakeEnumeratedRange(PhaseKind::FIRST, PhaseKind::LIMIT);
+}
+
+static inline auto MajorGCPhaseKinds() {
+ return mozilla::MakeEnumeratedRange(PhaseKind::GC_BEGIN,
+ PhaseKind(size_t(PhaseKind::GC_END) + 1));
+}
+
+static const char* ExplainGCOptions(JS::GCOptions options) {
+ switch (options) {
+ case JS::GCOptions::Normal:
+ return "Normal";
+ case JS::GCOptions::Shrink:
+ return "Shrink";
+ case JS::GCOptions::Shutdown:
+ return "Shutdown";
+ }
+
+ MOZ_CRASH("Unexpected GCOptions value");
+}
+
+JS_PUBLIC_API const char* JS::ExplainGCReason(JS::GCReason reason) {
+ switch (reason) {
+#define SWITCH_REASON(name, _) \
+ case JS::GCReason::name: \
+ return #name;
+ GCREASONS(SWITCH_REASON)
+#undef SWITCH_REASON
+
+ case JS::GCReason::NO_REASON:
+ return "NO_REASON";
+
+ default:
+ MOZ_CRASH("bad GC reason");
+ }
+}
+
+JS_PUBLIC_API bool JS::InternalGCReason(JS::GCReason reason) {
+ return reason < JS::GCReason::FIRST_FIREFOX_REASON;
+}
+
+const char* js::gcstats::ExplainAbortReason(GCAbortReason reason) {
+ switch (reason) {
+#define SWITCH_REASON(name, _) \
+ case GCAbortReason::name: \
+ return #name;
+ GC_ABORT_REASONS(SWITCH_REASON)
+
+ default:
+ MOZ_CRASH("bad GC abort reason");
+#undef SWITCH_REASON
+ }
+}
+
+static FILE* MaybeOpenFileFromEnv(const char* env,
+ FILE* defaultFile = nullptr) {
+ const char* value = getenv(env);
+ if (!value) {
+ return defaultFile;
+ }
+
+ FILE* file;
+ if (strcmp(value, "none") == 0) {
+ file = nullptr;
+ } else if (strcmp(value, "stdout") == 0) {
+ file = stdout;
+ } else if (strcmp(value, "stderr") == 0) {
+ file = stderr;
+ } else {
+ char path[300];
+ if (value[0] != '/') {
+ const char* dir = getenv("MOZ_UPLOAD_DIR");
+ if (dir) {
+ SprintfLiteral(path, "%s/%s", dir, value);
+ value = path;
+ }
+ }
+
+ file = fopen(value, "a");
+ if (!file || setvbuf(file, nullptr, _IOLBF, 256) != 0) {
+ perror("Error opening log file");
+ MOZ_CRASH("Failed to open log file.");
+ }
+ }
+
+ return file;
+}
+
+struct PhaseKindInfo {
+ Phase firstPhase;
+ uint8_t telemetryBucket;
+ const char* name;
+};
+
+// PhaseInfo objects form a tree.
+struct PhaseInfo {
+ Phase parent;
+ Phase firstChild;
+ Phase nextSibling;
+ Phase nextWithPhaseKind;
+ PhaseKind phaseKind;
+ uint8_t depth;
+ const char* name;
+ const char* path;
+};
+
+// A table of PhaseInfo indexed by Phase.
+using PhaseTable = EnumeratedArray<Phase, Phase::LIMIT, PhaseInfo>;
+
+// A table of PhaseKindInfo indexed by PhaseKind.
+using PhaseKindTable =
+ EnumeratedArray<PhaseKind, PhaseKind::LIMIT, PhaseKindInfo>;
+
+#include "gc/StatsPhasesGenerated.inc"
+
+// Iterate the phases in a phase kind.
+class PhaseIter {
+ Phase phase;
+
+ public:
+ explicit PhaseIter(PhaseKind kind) : phase(phaseKinds[kind].firstPhase) {}
+ bool done() const { return phase == Phase::NONE; }
+ void next() { phase = phases[phase].nextWithPhaseKind; }
+ Phase get() const { return phase; }
+ operator Phase() const { return phase; }
+};
+
+static double t(TimeDuration duration) { return duration.ToMilliseconds(); }
+
+inline JSContext* Statistics::context() {
+ return gc->rt->mainContextFromOwnThread();
+}
+
+inline Phase Statistics::currentPhase() const {
+ return phaseStack.empty() ? Phase::NONE : phaseStack.back();
+}
+
+PhaseKind Statistics::currentPhaseKind() const {
+ // Public API to get the current phase kind, suppressing the synthetic
+ // PhaseKind::MUTATOR phase.
+
+ Phase phase = currentPhase();
+ MOZ_ASSERT_IF(phase == Phase::MUTATOR, phaseStack.length() == 1);
+ if (phase == Phase::NONE || phase == Phase::MUTATOR) {
+ return PhaseKind::NONE;
+ }
+
+ return phases[phase].phaseKind;
+}
+
+static Phase LookupPhaseWithParent(PhaseKind phaseKind, Phase parentPhase) {
+ for (PhaseIter phase(phaseKind); !phase.done(); phase.next()) {
+ if (phases[phase].parent == parentPhase) {
+ return phase;
+ }
+ }
+
+ return Phase::NONE;
+}
+
+static const char* PhaseKindName(PhaseKind kind) {
+ if (kind == PhaseKind::NONE) {
+ return "NONE";
+ }
+
+ return phaseKinds[kind].name;
+}
+
+Phase Statistics::lookupChildPhase(PhaseKind phaseKind) const {
+ if (phaseKind == PhaseKind::IMPLICIT_SUSPENSION) {
+ return Phase::IMPLICIT_SUSPENSION;
+ }
+ if (phaseKind == PhaseKind::EXPLICIT_SUSPENSION) {
+ return Phase::EXPLICIT_SUSPENSION;
+ }
+
+ MOZ_ASSERT(phaseKind < PhaseKind::LIMIT);
+
+ // Search all expanded phases that correspond to the required
+ // phase to find the one whose parent is the current expanded phase.
+ Phase phase = LookupPhaseWithParent(phaseKind, currentPhase());
+
+ if (phase == Phase::NONE) {
+ MOZ_CRASH_UNSAFE_PRINTF(
+ "Child phase kind %s not found under current phase kind %s",
+ PhaseKindName(phaseKind), PhaseKindName(currentPhaseKind()));
+ }
+
+ return phase;
+}
+
+inline auto AllPhases() {
+ return mozilla::MakeEnumeratedRange(Phase::FIRST, Phase::LIMIT);
+}
+
+void Statistics::gcDuration(TimeDuration* total, TimeDuration* maxPause) const {
+ *total = *maxPause = 0;
+ for (auto& slice : slices_) {
+ *total += slice.duration();
+ if (slice.duration() > *maxPause) {
+ *maxPause = slice.duration();
+ }
+ }
+ if (*maxPause > maxPauseInInterval) {
+ maxPauseInInterval = *maxPause;
+ }
+}
+
+void Statistics::sccDurations(TimeDuration* total,
+ TimeDuration* maxPause) const {
+ *total = *maxPause = 0;
+ for (size_t i = 0; i < sccTimes.length(); i++) {
+ *total += sccTimes[i];
+ *maxPause = std::max(*maxPause, sccTimes[i]);
+ }
+}
+
+typedef Vector<UniqueChars, 8, SystemAllocPolicy> FragmentVector;
+
+static UniqueChars Join(const FragmentVector& fragments,
+ const char* separator = "") {
+ const size_t separatorLength = strlen(separator);
+ size_t length = 0;
+ for (size_t i = 0; i < fragments.length(); ++i) {
+ length += fragments[i] ? strlen(fragments[i].get()) : 0;
+ if (i < (fragments.length() - 1)) {
+ length += separatorLength;
+ }
+ }
+
+ char* joined = js_pod_malloc<char>(length + 1);
+ if (!joined) {
+ return UniqueChars();
+ }
+
+ joined[length] = '\0';
+ char* cursor = joined;
+ for (size_t i = 0; i < fragments.length(); ++i) {
+ if (fragments[i]) {
+ strcpy(cursor, fragments[i].get());
+ }
+ cursor += fragments[i] ? strlen(fragments[i].get()) : 0;
+ if (i < (fragments.length() - 1)) {
+ if (separatorLength) {
+ strcpy(cursor, separator);
+ }
+ cursor += separatorLength;
+ }
+ }
+
+ return UniqueChars(joined);
+}
+
+static TimeDuration SumChildTimes(Phase phase,
+ const Statistics::PhaseTimes& phaseTimes) {
+ TimeDuration total = 0;
+ for (phase = phases[phase].firstChild; phase != Phase::NONE;
+ phase = phases[phase].nextSibling) {
+ total += phaseTimes[phase];
+ }
+ return total;
+}
+
+UniqueChars Statistics::formatCompactSliceMessage() const {
+ // Skip if we OOM'ed.
+ if (slices_.length() == 0) {
+ return UniqueChars(nullptr);
+ }
+
+ const size_t index = slices_.length() - 1;
+ const SliceData& slice = slices_.back();
+
+ char budgetDescription[200];
+ slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
+
+ const char* format =
+ "GC Slice %u - Pause: %.3fms of %s budget (@ %.3fms); Reason: %s; Reset: "
+ "%s%s; Times: ";
+ char buffer[1024];
+ SprintfLiteral(buffer, format, index, t(slice.duration()), budgetDescription,
+ t(slice.start - slices_[0].start),
+ ExplainGCReason(slice.reason),
+ slice.wasReset() ? "yes - " : "no",
+ slice.wasReset() ? ExplainAbortReason(slice.resetReason) : "");
+
+ FragmentVector fragments;
+ if (!fragments.append(DuplicateString(buffer)) ||
+ !fragments.append(
+ formatCompactSlicePhaseTimes(slices_[index].phaseTimes))) {
+ return UniqueChars(nullptr);
+ }
+ return Join(fragments);
+}
+
+UniqueChars Statistics::formatCompactSummaryMessage() const {
+ FragmentVector fragments;
+ if (!fragments.append(DuplicateString("Summary - "))) {
+ return UniqueChars(nullptr);
+ }
+
+ TimeDuration total, longest;
+ gcDuration(&total, &longest);
+
+ const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
+ const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
+
+ char buffer[1024];
+ if (!nonincremental()) {
+ SprintfLiteral(buffer,
+ "Max Pause: %.3fms; MMU 20ms: %.1f%%; MMU 50ms: %.1f%%; "
+ "Total: %.3fms; ",
+ t(longest), mmu20 * 100., mmu50 * 100., t(total));
+ } else {
+ SprintfLiteral(buffer, "Non-Incremental: %.3fms (%s); ", t(total),
+ ExplainAbortReason(nonincrementalReason_));
+ }
+ if (!fragments.append(DuplicateString(buffer))) {
+ return UniqueChars(nullptr);
+ }
+
+ SprintfLiteral(buffer,
+ "Zones: %d of %d (-%d); Compartments: %d of %d (-%d); "
+ "HeapSize: %.3f MiB; "
+ "HeapChange (abs): %+d (%u); ",
+ zoneStats.collectedZoneCount, zoneStats.zoneCount,
+ zoneStats.sweptZoneCount, zoneStats.collectedCompartmentCount,
+ zoneStats.compartmentCount, zoneStats.sweptCompartmentCount,
+ double(preTotalHeapBytes) / BYTES_PER_MB,
+ int32_t(counts[COUNT_NEW_CHUNK] - counts[COUNT_DESTROY_CHUNK]),
+ counts[COUNT_NEW_CHUNK] + counts[COUNT_DESTROY_CHUNK]);
+ if (!fragments.append(DuplicateString(buffer))) {
+ return UniqueChars(nullptr);
+ }
+
+ MOZ_ASSERT_IF(counts[COUNT_ARENA_RELOCATED],
+ gcOptions == JS::GCOptions::Shrink);
+ if (gcOptions == JS::GCOptions::Shrink) {
+ SprintfLiteral(
+ buffer, "Kind: %s; Relocated: %.3f MiB; ", ExplainGCOptions(gcOptions),
+ double(ArenaSize * counts[COUNT_ARENA_RELOCATED]) / BYTES_PER_MB);
+ if (!fragments.append(DuplicateString(buffer))) {
+ return UniqueChars(nullptr);
+ }
+ }
+
+ return Join(fragments);
+}
+
+UniqueChars Statistics::formatCompactSlicePhaseTimes(
+ const PhaseTimes& phaseTimes) const {
+ static const TimeDuration MaxUnaccountedTime =
+ TimeDuration::FromMicroseconds(100);
+
+ FragmentVector fragments;
+ char buffer[128];
+ for (auto phase : AllPhases()) {
+ DebugOnly<uint8_t> level = phases[phase].depth;
+ MOZ_ASSERT(level < 4);
+
+ TimeDuration ownTime = phaseTimes[phase];
+ TimeDuration childTime = SumChildTimes(phase, phaseTimes);
+ if (ownTime > MaxUnaccountedTime) {
+ SprintfLiteral(buffer, "%s: %.3fms", phases[phase].name, t(ownTime));
+ if (!fragments.append(DuplicateString(buffer))) {
+ return UniqueChars(nullptr);
+ }
+
+ if (childTime && (ownTime - childTime) > MaxUnaccountedTime) {
+ MOZ_ASSERT(level < 3);
+ SprintfLiteral(buffer, "%s: %.3fms", "Other", t(ownTime - childTime));
+ if (!fragments.append(DuplicateString(buffer))) {
+ return UniqueChars(nullptr);
+ }
+ }
+ }
+ }
+ return Join(fragments, ", ");
+}
+
+UniqueChars Statistics::formatDetailedMessage() const {
+ FragmentVector fragments;
+
+ if (!fragments.append(formatDetailedDescription())) {
+ return UniqueChars(nullptr);
+ }
+
+ if (!slices_.empty()) {
+ for (unsigned i = 0; i < slices_.length(); i++) {
+ if (!fragments.append(formatDetailedSliceDescription(i, slices_[i]))) {
+ return UniqueChars(nullptr);
+ }
+ if (!fragments.append(formatDetailedPhaseTimes(slices_[i].phaseTimes))) {
+ return UniqueChars(nullptr);
+ }
+ }
+ }
+ if (!fragments.append(formatDetailedTotals())) {
+ return UniqueChars(nullptr);
+ }
+ if (!fragments.append(formatDetailedPhaseTimes(phaseTimes))) {
+ return UniqueChars(nullptr);
+ }
+
+ return Join(fragments);
+}
+
+UniqueChars Statistics::formatDetailedDescription() const {
+ TimeDuration sccTotal, sccLongest;
+ sccDurations(&sccTotal, &sccLongest);
+
+ const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
+ const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
+
+ const char* format =
+ "=================================================================\n\
+ Invocation Kind: %s\n\
+ Reason: %s\n\
+ Incremental: %s%s\n\
+ Zones Collected: %d of %d (-%d)\n\
+ Compartments Collected: %d of %d (-%d)\n\
+ MinorGCs since last GC: %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\
+ Arenas Relocated: %.3f MiB\n\
+";
+
+ char buffer[1024];
+ SprintfLiteral(
+ buffer, format, ExplainGCOptions(gcOptions),
+ ExplainGCReason(slices_[0].reason), nonincremental() ? "no - " : "yes",
+ nonincremental() ? ExplainAbortReason(nonincrementalReason_) : "",
+ zoneStats.collectedZoneCount, zoneStats.zoneCount,
+ zoneStats.sweptZoneCount, zoneStats.collectedCompartmentCount,
+ zoneStats.compartmentCount, zoneStats.sweptCompartmentCount,
+ getCount(COUNT_MINOR_GC), getCount(COUNT_STOREBUFFER_OVERFLOW),
+ mmu20 * 100., mmu50 * 100., t(sccTotal), t(sccLongest),
+ double(preTotalHeapBytes) / BYTES_PER_MB,
+ getCount(COUNT_NEW_CHUNK) - getCount(COUNT_DESTROY_CHUNK),
+ getCount(COUNT_NEW_CHUNK) + getCount(COUNT_DESTROY_CHUNK),
+ double(ArenaSize * getCount(COUNT_ARENA_RELOCATED)) / BYTES_PER_MB);
+
+ return DuplicateString(buffer);
+}
+
+UniqueChars Statistics::formatDetailedSliceDescription(
+ unsigned i, const SliceData& slice) const {
+ char budgetDescription[200];
+ slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
+
+ const char* format =
+ "\
+ ---- Slice %u ----\n\
+ Reason: %s\n\
+ Trigger: %s\n\
+ Reset: %s%s\n\
+ State: %s -> %s\n\
+ Page Faults: %" PRIu64
+ "\n\
+ Pause: %.3fms of %s budget (@ %.3fms)\n\
+";
+
+ char triggerBuffer[100] = "n/a";
+ if (slice.trigger) {
+ Trigger trigger = slice.trigger.value();
+ SprintfLiteral(triggerBuffer, "%.3f MiB of %.3f MiB threshold\n",
+ double(trigger.amount) / BYTES_PER_MB,
+ double(trigger.threshold) / BYTES_PER_MB);
+ }
+
+ char buffer[1024];
+ SprintfLiteral(
+ buffer, format, i, ExplainGCReason(slice.reason), triggerBuffer,
+ slice.wasReset() ? "yes - " : "no",
+ slice.wasReset() ? ExplainAbortReason(slice.resetReason) : "",
+ gc::StateName(slice.initialState), gc::StateName(slice.finalState),
+ uint64_t(slice.endFaults - slice.startFaults), t(slice.duration()),
+ budgetDescription, t(slice.start - slices_[0].start));
+ return DuplicateString(buffer);
+}
+
+static bool IncludePhase(TimeDuration duration) {
+ // Don't include durations that will print as "0.000ms".
+ return duration.ToMilliseconds() >= 0.001;
+}
+
+UniqueChars Statistics::formatDetailedPhaseTimes(
+ const PhaseTimes& phaseTimes) const {
+ static const TimeDuration MaxUnaccountedChildTime =
+ TimeDuration::FromMicroseconds(50);
+
+ FragmentVector fragments;
+ char buffer[128];
+ for (auto phase : AllPhases()) {
+ uint8_t level = phases[phase].depth;
+ TimeDuration ownTime = phaseTimes[phase];
+ TimeDuration childTime = SumChildTimes(phase, phaseTimes);
+ if (IncludePhase(ownTime)) {
+ SprintfLiteral(buffer, " %*s%s: %.3fms\n", level * 2, "",
+ phases[phase].name, t(ownTime));
+ if (!fragments.append(DuplicateString(buffer))) {
+ return UniqueChars(nullptr);
+ }
+
+ if (childTime && (ownTime - childTime) > MaxUnaccountedChildTime) {
+ SprintfLiteral(buffer, " %*s%s: %.3fms\n", (level + 1) * 2, "",
+ "Other", t(ownTime - childTime));
+ if (!fragments.append(DuplicateString(buffer))) {
+ return UniqueChars(nullptr);
+ }
+ }
+ }
+ }
+ return Join(fragments);
+}
+
+UniqueChars Statistics::formatDetailedTotals() const {
+ TimeDuration total, longest;
+ gcDuration(&total, &longest);
+
+ const char* format =
+ "\
+ ---- Totals ----\n\
+ Total Time: %.3fms\n\
+ Max Pause: %.3fms\n\
+";
+ char buffer[1024];
+ SprintfLiteral(buffer, format, t(total), t(longest));
+ return DuplicateString(buffer);
+}
+
+void Statistics::formatJsonSlice(size_t sliceNum, JSONPrinter& json) const {
+ /*
+ * We number each of the slice properties to keep the code in
+ * GCTelemetry.jsm in sync. See MAX_SLICE_KEYS.
+ */
+ json.beginObject();
+ formatJsonSliceDescription(sliceNum, slices_[sliceNum], json); // # 1-11
+
+ json.beginObjectProperty("times"); // # 12
+ formatJsonPhaseTimes(slices_[sliceNum].phaseTimes, json);
+ json.endObject();
+
+ json.endObject();
+}
+
+UniqueChars Statistics::renderJsonSlice(size_t sliceNum) const {
+ Sprinter printer(nullptr, false);
+ if (!printer.init()) {
+ return UniqueChars(nullptr);
+ }
+ JSONPrinter json(printer, false);
+
+ formatJsonSlice(sliceNum, json);
+ return printer.release();
+}
+
+UniqueChars Statistics::renderNurseryJson() const {
+ Sprinter printer(nullptr, false);
+ if (!printer.init()) {
+ return UniqueChars(nullptr);
+ }
+ JSONPrinter json(printer, false);
+ gc->nursery().renderProfileJSON(json);
+ return printer.release();
+}
+
+#ifdef DEBUG
+void Statistics::log(const char* fmt, ...) {
+ va_list args;
+ va_start(args, fmt);
+ if (gcDebugFile) {
+ TimeDuration sinceStart = TimeStamp::Now() - TimeStamp::FirstTimeStamp();
+ fprintf(gcDebugFile, "%12.3f: ", sinceStart.ToMicroseconds());
+ vfprintf(gcDebugFile, fmt, args);
+ fprintf(gcDebugFile, "\n");
+ fflush(gcDebugFile);
+ }
+ va_end(args);
+}
+#endif
+
+UniqueChars Statistics::renderJsonMessage() const {
+ /*
+ * The format of the JSON message is specified by the GCMajorMarkerPayload
+ * type in profiler.firefox.com
+ * https://github.com/firefox-devtools/profiler/blob/master/src/types/markers.js#L62
+ *
+ * All the properties listed here are created within the timings property
+ * of the GCMajor marker.
+ */
+ if (aborted) {
+ return DuplicateString("{status:\"aborted\"}"); // May return nullptr
+ }
+
+ Sprinter printer(nullptr, false);
+ if (!printer.init()) {
+ return UniqueChars(nullptr);
+ }
+ JSONPrinter json(printer, false);
+
+ json.beginObject();
+ json.property("status", "completed");
+ formatJsonDescription(json);
+
+ json.beginObjectProperty("totals");
+ formatJsonPhaseTimes(phaseTimes, json);
+ json.endObject();
+
+ json.endObject();
+
+ return printer.release();
+}
+
+void Statistics::formatJsonDescription(JSONPrinter& json) const {
+ // If you change JSON properties here, please update:
+ // Firefox Profiler:
+ // https://github.com/firefox-devtools/profiler
+
+ TimeDuration total, longest;
+ gcDuration(&total, &longest);
+ json.property("max_pause", longest, JSONPrinter::MILLISECONDS);
+ json.property("total_time", total, JSONPrinter::MILLISECONDS);
+ // We might be able to omit reason if profiler.firefox.com was able to retrive
+ // it from the first slice. But it doesn't do this yet.
+ json.property("reason", ExplainGCReason(slices_[0].reason));
+ json.property("zones_collected", zoneStats.collectedZoneCount);
+ json.property("total_zones", zoneStats.zoneCount);
+ json.property("total_compartments", zoneStats.compartmentCount);
+ json.property("minor_gcs", getCount(COUNT_MINOR_GC));
+ json.property("minor_gc_number", gc->minorGCCount());
+ json.property("major_gc_number", gc->majorGCCount());
+ uint32_t storebufferOverflows = getCount(COUNT_STOREBUFFER_OVERFLOW);
+ if (storebufferOverflows) {
+ json.property("store_buffer_overflows", storebufferOverflows);
+ }
+ json.property("slices", slices_.length());
+
+ const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
+ const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
+ json.property("mmu_20ms", int(mmu20 * 100));
+ json.property("mmu_50ms", int(mmu50 * 100));
+
+ TimeDuration sccTotal, sccLongest;
+ sccDurations(&sccTotal, &sccLongest);
+ json.property("scc_sweep_total", sccTotal, JSONPrinter::MILLISECONDS);
+ json.property("scc_sweep_max_pause", sccLongest, JSONPrinter::MILLISECONDS);
+
+ if (nonincrementalReason_ != GCAbortReason::None) {
+ json.property("nonincremental_reason",
+ ExplainAbortReason(nonincrementalReason_));
+ }
+ json.property("allocated_bytes", preTotalHeapBytes);
+ json.property("post_heap_size", postTotalHeapBytes);
+
+ uint32_t addedChunks = getCount(COUNT_NEW_CHUNK);
+ if (addedChunks) {
+ json.property("added_chunks", addedChunks);
+ }
+ uint32_t removedChunks = getCount(COUNT_DESTROY_CHUNK);
+ if (removedChunks) {
+ json.property("removed_chunks", removedChunks);
+ }
+ json.property("major_gc_number", startingMajorGCNumber);
+ json.property("minor_gc_number", startingMinorGCNumber);
+ json.property("slice_number", startingSliceNumber);
+}
+
+void Statistics::formatJsonSliceDescription(unsigned i, const SliceData& slice,
+ JSONPrinter& json) const {
+ // If you change JSON properties here, please update:
+ // Firefox Profiler:
+ // https://github.com/firefox-devtools/profiler
+ //
+ char budgetDescription[200];
+ slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
+ TimeStamp originTime = TimeStamp::ProcessCreation();
+
+ json.property("slice", i);
+ json.property("pause", slice.duration(), JSONPrinter::MILLISECONDS);
+ json.property("reason", ExplainGCReason(slice.reason));
+ json.property("initial_state", gc::StateName(slice.initialState));
+ json.property("final_state", gc::StateName(slice.finalState));
+ json.property("budget", budgetDescription);
+ json.property("major_gc_number", startingMajorGCNumber);
+ if (slice.trigger) {
+ Trigger trigger = slice.trigger.value();
+ json.property("trigger_amount", trigger.amount);
+ json.property("trigger_threshold", trigger.threshold);
+ }
+ int64_t numFaults = slice.endFaults - slice.startFaults;
+ if (numFaults != 0) {
+ json.property("page_faults", numFaults);
+ }
+ json.property("start_timestamp", slice.start - originTime,
+ JSONPrinter::SECONDS);
+}
+
+void Statistics::formatJsonPhaseTimes(const PhaseTimes& phaseTimes,
+ JSONPrinter& json) const {
+ for (auto phase : AllPhases()) {
+ TimeDuration ownTime = phaseTimes[phase];
+ if (!ownTime.IsZero()) {
+ json.property(phases[phase].path, ownTime, JSONPrinter::MILLISECONDS);
+ }
+ }
+}
+
+Statistics::Statistics(GCRuntime* gc)
+ : gc(gc),
+ gcTimerFile(nullptr),
+ gcDebugFile(nullptr),
+ nonincrementalReason_(GCAbortReason::None),
+ creationTime_(TimeStamp::Now()),
+ tenuredAllocsSinceMinorGC(0),
+ preTotalHeapBytes(0),
+ postTotalHeapBytes(0),
+ preCollectedHeapBytes(0),
+ startingMinorGCNumber(0),
+ startingMajorGCNumber(0),
+ startingSliceNumber(0),
+ maxPauseInInterval(0),
+ sliceCallback(nullptr),
+ nurseryCollectionCallback(nullptr),
+ aborted(false),
+ enableProfiling_(false),
+ sliceCount_(0) {
+ for (auto& count : counts) {
+ count = 0;
+ }
+
+ for (auto& stat : stats) {
+ stat = 0;
+ }
+
+#ifdef DEBUG
+ for (const auto& duration : totalTimes_) {
+ using ElementType = std::remove_reference_t<decltype(duration)>;
+ static_assert(!std::is_trivially_constructible_v<ElementType>,
+ "Statistics::Statistics will only initialize "
+ "totalTimes_'s elements if their default constructor is "
+ "non-trivial");
+ MOZ_ASSERT(duration.IsZero(),
+ "totalTimes_ default-initialization should have "
+ "default-initialized every element of totalTimes_ to zero");
+ }
+#endif
+
+ MOZ_ALWAYS_TRUE(phaseStack.reserve(MAX_PHASE_NESTING));
+ MOZ_ALWAYS_TRUE(suspendedPhases.reserve(MAX_SUSPENDED_PHASES));
+
+ gcTimerFile = MaybeOpenFileFromEnv("MOZ_GCTIMER");
+ gcDebugFile = MaybeOpenFileFromEnv("JS_GC_DEBUG");
+ gcProfileFile = MaybeOpenFileFromEnv("JS_GC_PROFILE_FILE", stderr);
+
+ gc::ReadProfileEnv("JS_GC_PROFILE",
+ "Report major GCs taking more than N milliseconds for "
+ "all or just the main runtime\n",
+ &enableProfiling_, &profileWorkers_, &profileThreshold_);
+}
+
+Statistics::~Statistics() {
+ if (gcTimerFile && gcTimerFile != stdout && gcTimerFile != stderr) {
+ fclose(gcTimerFile);
+ }
+ if (gcDebugFile && gcDebugFile != stdout && gcDebugFile != stderr) {
+ fclose(gcDebugFile);
+ }
+}
+
+/* static */
+bool Statistics::initialize() {
+#ifdef DEBUG
+ // Sanity check generated tables.
+ for (auto i : AllPhases()) {
+ auto parent = phases[i].parent;
+ if (parent != Phase::NONE) {
+ MOZ_ASSERT(phases[i].depth == phases[parent].depth + 1);
+ }
+ auto firstChild = phases[i].firstChild;
+ if (firstChild != Phase::NONE) {
+ MOZ_ASSERT(i == phases[firstChild].parent);
+ MOZ_ASSERT(phases[i].depth == phases[firstChild].depth - 1);
+ }
+ auto nextSibling = phases[i].nextSibling;
+ if (nextSibling != Phase::NONE) {
+ MOZ_ASSERT(parent == phases[nextSibling].parent);
+ MOZ_ASSERT(phases[i].depth == phases[nextSibling].depth);
+ }
+ auto nextWithPhaseKind = phases[i].nextWithPhaseKind;
+ if (nextWithPhaseKind != Phase::NONE) {
+ MOZ_ASSERT(phases[i].phaseKind == phases[nextWithPhaseKind].phaseKind);
+ MOZ_ASSERT(parent != phases[nextWithPhaseKind].parent);
+ }
+ }
+ for (auto i : AllPhaseKinds()) {
+ MOZ_ASSERT(phases[phaseKinds[i].firstPhase].phaseKind == i);
+ for (auto j : AllPhaseKinds()) {
+ MOZ_ASSERT_IF(i != j, phaseKinds[i].telemetryBucket !=
+ phaseKinds[j].telemetryBucket);
+ }
+ }
+#endif
+
+ return true;
+}
+
+JS::GCSliceCallback Statistics::setSliceCallback(
+ JS::GCSliceCallback newCallback) {
+ JS::GCSliceCallback oldCallback = sliceCallback;
+ sliceCallback = newCallback;
+ return oldCallback;
+}
+
+JS::GCNurseryCollectionCallback Statistics::setNurseryCollectionCallback(
+ JS::GCNurseryCollectionCallback newCallback) {
+ auto oldCallback = nurseryCollectionCallback;
+ nurseryCollectionCallback = newCallback;
+ return oldCallback;
+}
+
+TimeDuration Statistics::clearMaxGCPauseAccumulator() {
+ TimeDuration prior = maxPauseInInterval;
+ maxPauseInInterval = 0;
+ return prior;
+}
+
+TimeDuration Statistics::getMaxGCPauseSinceClear() {
+ return maxPauseInInterval;
+}
+
+// Sum up the time for a phase, including instances of the phase with different
+// parents.
+static TimeDuration SumPhase(PhaseKind phaseKind,
+ const Statistics::PhaseTimes& times) {
+ TimeDuration sum;
+ for (PhaseIter phase(phaseKind); !phase.done(); phase.next()) {
+ sum += times[phase];
+ }
+ return sum;
+}
+
+static bool CheckSelfTime(Phase parent, Phase child,
+ const Statistics::PhaseTimes& times,
+ const Statistics::PhaseTimes& selfTimes,
+ TimeDuration childTime) {
+ if (selfTimes[parent] < childTime) {
+ fprintf(
+ stderr,
+ "Parent %s time = %.3fms with %.3fms remaining, child %s time %.3fms\n",
+ phases[parent].name, times[parent].ToMilliseconds(),
+ selfTimes[parent].ToMilliseconds(), phases[child].name,
+ childTime.ToMilliseconds());
+ fflush(stderr);
+ return false;
+ }
+
+ return true;
+}
+
+static PhaseKind FindLongestPhaseKind(const Statistics::PhaseKindTimes& times) {
+ TimeDuration longestTime;
+ PhaseKind phaseKind = PhaseKind::NONE;
+ for (auto i : MajorGCPhaseKinds()) {
+ if (times[i] > longestTime) {
+ longestTime = times[i];
+ phaseKind = i;
+ }
+ }
+
+ return phaseKind;
+}
+
+static PhaseKind LongestPhaseSelfTimeInMajorGC(
+ const Statistics::PhaseTimes& times) {
+ // Start with total times per expanded phase, including children's times.
+ Statistics::PhaseTimes selfTimes(times);
+
+ // We have the total time spent in each phase, including descendant times.
+ // Loop over the children and subtract their times from their parent's self
+ // time.
+ for (auto i : AllPhases()) {
+ Phase parent = phases[i].parent;
+ if (parent != Phase::NONE) {
+ bool ok = CheckSelfTime(parent, i, times, selfTimes, times[i]);
+
+ // This happens very occasionally in release builds and frequently
+ // in Windows debug builds. Skip collecting longest phase telemetry
+ // if it does.
+#ifndef XP_WIN
+ MOZ_ASSERT(ok, "Inconsistent time data; see bug 1400153");
+#endif
+ if (!ok) {
+ return PhaseKind::NONE;
+ }
+
+ selfTimes[parent] -= times[i];
+ }
+ }
+
+ // Sum expanded phases corresponding to the same phase.
+ Statistics::PhaseKindTimes phaseKindTimes;
+ for (auto i : AllPhaseKinds()) {
+ phaseKindTimes[i] = SumPhase(i, selfTimes);
+ }
+
+ return FindLongestPhaseKind(phaseKindTimes);
+}
+
+void Statistics::printStats() {
+ if (aborted) {
+ fprintf(gcTimerFile,
+ "OOM during GC statistics collection. The report is unavailable "
+ "for this GC.\n");
+ } else {
+ UniqueChars msg = formatDetailedMessage();
+ if (msg) {
+ double secSinceStart =
+ (slices_[0].start - TimeStamp::ProcessCreation()).ToSeconds();
+ fprintf(gcTimerFile, "GC(T+%.3fs) %s\n", secSinceStart, msg.get());
+ }
+ }
+ fflush(gcTimerFile);
+}
+
+void Statistics::beginGC(JS::GCOptions options, const TimeStamp& currentTime) {
+ slices_.clearAndFree();
+ sccTimes.clearAndFree();
+ gcOptions = options;
+ nonincrementalReason_ = GCAbortReason::None;
+
+ preTotalHeapBytes = gc->heapSize.bytes();
+
+ preCollectedHeapBytes = 0;
+
+ startingMajorGCNumber = gc->majorGCCount();
+ startingSliceNumber = gc->gcNumber();
+
+ if (gc->lastGCEndTime()) {
+ timeSinceLastGC = currentTime - gc->lastGCEndTime();
+ }
+
+ totalGCTime_ = TimeDuration();
+}
+
+void Statistics::measureInitialHeapSize() {
+ MOZ_ASSERT(preCollectedHeapBytes == 0);
+ for (GCZonesIter zone(gc); !zone.done(); zone.next()) {
+ preCollectedHeapBytes += zone->gcHeapSize.bytes();
+ }
+}
+
+void Statistics::endGC() {
+ postTotalHeapBytes = gc->heapSize.bytes();
+
+ sendGCTelemetry();
+}
+
+TimeDuration Statistics::sumTotalParallelTime(PhaseKind phaseKind) const {
+ TimeDuration total;
+ for (const SliceData& slice : slices_) {
+ total += slice.totalParallelTimes[phaseKind];
+ }
+ return total;
+}
+
+void Statistics::sendGCTelemetry() {
+ JSRuntime* runtime = gc->rt;
+ // NOTE: "Compartmental" is term that was deprecated with the
+ // introduction of zone-based GC, but the old telemetry probe
+ // continues to be used.
+ runtime->metrics().GC_IS_COMPARTMENTAL(!gc->fullGCRequested);
+ runtime->metrics().GC_ZONE_COUNT(zoneStats.zoneCount);
+ runtime->metrics().GC_ZONES_COLLECTED(zoneStats.collectedZoneCount);
+
+ TimeDuration prepareTotal = phaseTimes[Phase::PREPARE];
+ TimeDuration markTotal = SumPhase(PhaseKind::MARK, phaseTimes);
+ TimeDuration markRootsTotal = SumPhase(PhaseKind::MARK_ROOTS, phaseTimes);
+
+ // Gray and weak marking time is counted under MARK_WEAK and not MARK_GRAY.
+ TimeDuration markWeakTotal = SumPhase(PhaseKind::MARK_WEAK, phaseTimes);
+ TimeDuration markGrayNotWeak =
+ SumPhase(PhaseKind::MARK_GRAY, phaseTimes) +
+ SumPhase(PhaseKind::MARK_INCOMING_GRAY, phaseTimes);
+ TimeDuration markGrayWeak = SumPhase(PhaseKind::MARK_GRAY_WEAK, phaseTimes);
+ TimeDuration markGrayTotal = markGrayNotWeak + markGrayWeak;
+ TimeDuration markNotGrayOrWeak = markTotal - markGrayNotWeak - markWeakTotal;
+ if (markNotGrayOrWeak < TimeDuration::FromMilliseconds(0)) {
+ markNotGrayOrWeak = TimeDuration();
+ }
+
+ size_t markCount = getCount(COUNT_CELLS_MARKED);
+
+ runtime->metrics().GC_PREPARE_MS(prepareTotal);
+ runtime->metrics().GC_MARK_MS(markNotGrayOrWeak);
+ if (markTotal >= TimeDuration::FromMicroseconds(1)) {
+ double markRate = double(markCount) / t(markTotal);
+ runtime->metrics().GC_MARK_RATE_2(uint32_t(markRate));
+ }
+ runtime->metrics().GC_SWEEP_MS(phaseTimes[Phase::SWEEP]);
+ if (gc->didCompactZones()) {
+ runtime->metrics().GC_COMPACT_MS(phaseTimes[Phase::COMPACT]);
+ }
+ runtime->metrics().GC_MARK_ROOTS_US(markRootsTotal);
+ runtime->metrics().GC_MARK_GRAY_MS_2(markGrayTotal);
+ runtime->metrics().GC_MARK_WEAK_MS(markWeakTotal);
+ runtime->metrics().GC_NON_INCREMENTAL(nonincremental());
+ if (nonincremental()) {
+ runtime->metrics().GC_NON_INCREMENTAL_REASON(
+ uint32_t(nonincrementalReason_));
+ }
+
+#ifdef DEBUG
+ // Reset happens non-incrementally, so only the last slice can be reset.
+ for (size_t i = 0; i < slices_.length() - 1; i++) {
+ MOZ_ASSERT(!slices_[i].wasReset());
+ }
+#endif
+ const auto& lastSlice = slices_.back();
+ runtime->metrics().GC_RESET(lastSlice.wasReset());
+ if (lastSlice.wasReset()) {
+ runtime->metrics().GC_RESET_REASON(uint32_t(lastSlice.resetReason));
+ }
+
+ TimeDuration total, longest;
+ gcDuration(&total, &longest);
+
+ runtime->metrics().GC_MS(total);
+ runtime->metrics().GC_MAX_PAUSE_MS_2(longest);
+
+ const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
+ runtime->metrics().GC_MMU_50(mmu50 * 100);
+
+ // Record scheduling telemetry for the main runtime but not for workers, which
+ // are scheduled differently.
+ if (!runtime->parentRuntime && timeSinceLastGC) {
+ runtime->metrics().GC_TIME_BETWEEN_S(timeSinceLastGC);
+ if (!nonincremental()) {
+ runtime->metrics().GC_SLICE_COUNT(slices_.length());
+ }
+ }
+
+ if (!lastSlice.wasReset() && preCollectedHeapBytes != 0) {
+ size_t bytesSurvived = 0;
+ for (ZonesIter zone(runtime, WithAtoms); !zone.done(); zone.next()) {
+ if (zone->wasCollected()) {
+ bytesSurvived += zone->gcHeapSize.retainedBytes();
+ }
+ }
+
+ MOZ_ASSERT(preCollectedHeapBytes >= bytesSurvived);
+ double survivalRate =
+ 100.0 * double(bytesSurvived) / double(preCollectedHeapBytes);
+ runtime->metrics().GC_TENURED_SURVIVAL_RATE(uint32_t(survivalRate));
+
+ // Calculate 'effectiveness' in MB / second, on main thread only for now.
+ if (!runtime->parentRuntime) {
+ size_t bytesFreed = preCollectedHeapBytes - bytesSurvived;
+ TimeDuration clampedTotal =
+ TimeDuration::Max(total, TimeDuration::FromMilliseconds(1));
+ double effectiveness =
+ (double(bytesFreed) / BYTES_PER_MB) / clampedTotal.ToSeconds();
+ runtime->metrics().GC_EFFECTIVENESS(uint32_t(effectiveness));
+ }
+ }
+
+ // Parallel marking stats.
+ if (gc->isParallelMarkingEnabled()) {
+ TimeDuration wallTime = SumPhase(PhaseKind::PARALLEL_MARK, phaseTimes);
+ TimeDuration parallelRunTime =
+ sumTotalParallelTime(PhaseKind::PARALLEL_MARK) -
+ sumTotalParallelTime(PhaseKind::PARALLEL_MARK_WAIT);
+ TimeDuration parallelMarkTime =
+ sumTotalParallelTime(PhaseKind::PARALLEL_MARK_MARK);
+ if (wallTime && parallelMarkTime) {
+ uint32_t threadCount = gc->markers.length();
+ double speedup = parallelMarkTime / wallTime;
+ double utilization = parallelRunTime / (wallTime * threadCount);
+ runtime->metrics().GC_PARALLEL_MARK_SPEEDUP(uint32_t(speedup * 100.0));
+ runtime->metrics().GC_PARALLEL_MARK_UTILIZATION(
+ std::clamp<uint32_t>(utilization * 100.0, 0, 100));
+ runtime->metrics().GC_PARALLEL_MARK_INTERRUPTIONS(
+ getCount(COUNT_PARALLEL_MARK_INTERRUPTIONS));
+ }
+ }
+}
+
+void Statistics::beginNurseryCollection(JS::GCReason reason) {
+ count(COUNT_MINOR_GC);
+ startingMinorGCNumber = gc->minorGCCount();
+ if (nurseryCollectionCallback) {
+ (*nurseryCollectionCallback)(
+ context(), JS::GCNurseryProgress::GC_NURSERY_COLLECTION_START, reason);
+ }
+}
+
+void Statistics::endNurseryCollection(JS::GCReason reason) {
+ if (nurseryCollectionCallback) {
+ (*nurseryCollectionCallback)(
+ context(), JS::GCNurseryProgress::GC_NURSERY_COLLECTION_END, reason);
+ }
+
+ tenuredAllocsSinceMinorGC = 0;
+}
+
+Statistics::SliceData::SliceData(const SliceBudget& budget,
+ Maybe<Trigger> trigger, JS::GCReason reason,
+ TimeStamp start, size_t startFaults,
+ gc::State initialState)
+ : budget(budget),
+ reason(reason),
+ trigger(trigger),
+ initialState(initialState),
+ start(start),
+ startFaults(startFaults) {}
+
+void Statistics::beginSlice(const ZoneGCStats& zoneStats, JS::GCOptions options,
+ const SliceBudget& budget, JS::GCReason reason,
+ bool budgetWasIncreased) {
+ MOZ_ASSERT(phaseStack.empty() ||
+ (phaseStack.length() == 1 && phaseStack[0] == Phase::MUTATOR));
+
+ this->zoneStats = zoneStats;
+
+ TimeStamp currentTime = TimeStamp::Now();
+
+ bool first = !gc->isIncrementalGCInProgress();
+ if (first) {
+ beginGC(options, currentTime);
+ }
+
+ JSRuntime* runtime = gc->rt;
+ if (!runtime->parentRuntime && !slices_.empty()) {
+ TimeDuration timeSinceLastSlice = currentTime - slices_.back().end;
+ runtime->metrics().GC_TIME_BETWEEN_SLICES_MS(timeSinceLastSlice);
+ }
+
+ Maybe<Trigger> trigger = recordedTrigger;
+ recordedTrigger.reset();
+
+ if (!slices_.emplaceBack(budget, trigger, reason, currentTime,
+ GetPageFaultCount(), gc->state())) {
+ // If we are OOM, set a flag to indicate we have missing slice data.
+ aborted = true;
+ return;
+ }
+
+ runtime->metrics().GC_REASON_2(uint32_t(reason));
+ runtime->metrics().GC_BUDGET_WAS_INCREASED(budgetWasIncreased);
+
+ // Slice callbacks should only fire for the outermost level.
+ if (sliceCallback) {
+ JSContext* cx = context();
+ JS::GCDescription desc(!gc->fullGCRequested, false, options, reason);
+ if (first) {
+ (*sliceCallback)(cx, JS::GC_CYCLE_BEGIN, desc);
+ }
+ (*sliceCallback)(cx, JS::GC_SLICE_BEGIN, desc);
+ }
+
+ log("begin slice");
+}
+
+void Statistics::endSlice() {
+ MOZ_ASSERT(phaseStack.empty() ||
+ (phaseStack.length() == 1 && phaseStack[0] == Phase::MUTATOR));
+
+ if (!aborted) {
+ auto& slice = slices_.back();
+ slice.end = TimeStamp::Now();
+ slice.endFaults = GetPageFaultCount();
+ slice.finalState = gc->state();
+
+ log("end slice");
+
+ sendSliceTelemetry(slice);
+
+ sliceCount_++;
+
+ totalGCTime_ += slice.end - slice.start;
+ }
+
+ bool last = !gc->isIncrementalGCInProgress();
+ if (last) {
+ if (gcTimerFile) {
+ printStats();
+ }
+
+ if (!aborted) {
+ endGC();
+ }
+ }
+
+ if (!aborted &&
+ ShouldPrintProfile(gc->rt, enableProfiling_, profileWorkers_,
+ profileThreshold_, slices_.back().duration())) {
+ printSliceProfile();
+ }
+
+ // Slice callbacks should only fire for the outermost level.
+ if (!aborted) {
+ if (sliceCallback) {
+ JSContext* cx = context();
+ JS::GCDescription desc(!gc->fullGCRequested, last, gcOptions,
+ slices_.back().reason);
+ (*sliceCallback)(cx, JS::GC_SLICE_END, desc);
+ if (last) {
+ (*sliceCallback)(cx, JS::GC_CYCLE_END, desc);
+ }
+ }
+ }
+
+ // Do this after the slice callback since it uses these values.
+ if (last) {
+ for (auto& count : counts) {
+ count = 0;
+ }
+
+ // Clear the timers at the end of a GC, preserving the data for
+ // PhaseKind::MUTATOR.
+ auto mutatorStartTime = phaseStartTimes[Phase::MUTATOR];
+ auto mutatorTime = phaseTimes[Phase::MUTATOR];
+
+ phaseStartTimes = PhaseTimeStamps();
+#ifdef DEBUG
+ phaseEndTimes = PhaseTimeStamps();
+#endif
+ phaseTimes = PhaseTimes();
+
+ phaseStartTimes[Phase::MUTATOR] = mutatorStartTime;
+ phaseTimes[Phase::MUTATOR] = mutatorTime;
+ }
+
+ aborted = false;
+}
+
+void Statistics::sendSliceTelemetry(const SliceData& slice) {
+ JSRuntime* runtime = gc->rt;
+ TimeDuration sliceTime = slice.end - slice.start;
+ runtime->metrics().GC_SLICE_MS(sliceTime);
+
+ if (slice.budget.isTimeBudget()) {
+ TimeDuration budgetDuration = slice.budget.timeBudgetDuration();
+ runtime->metrics().GC_BUDGET_MS_2(budgetDuration);
+
+ if (IsCurrentlyAnimating(runtime->lastAnimationTime, slice.end)) {
+ runtime->metrics().GC_ANIMATION_MS(sliceTime);
+ }
+
+ bool wasLongSlice = false;
+ if (sliceTime > budgetDuration) {
+ // Record how long we went over budget.
+ TimeDuration overrun = sliceTime - budgetDuration;
+ runtime->metrics().GC_BUDGET_OVERRUN(overrun);
+
+ // Long GC slices are those that go 50% or 5ms over their budget.
+ wasLongSlice = (overrun > TimeDuration::FromMilliseconds(5)) ||
+ (overrun > (budgetDuration / int64_t(2)));
+
+ // Record the longest phase in any long slice.
+ if (wasLongSlice) {
+ PhaseKind longest = LongestPhaseSelfTimeInMajorGC(slice.phaseTimes);
+ reportLongestPhaseInMajorGC(longest, [runtime](auto sample) {
+ runtime->metrics().GC_SLOW_PHASE(sample);
+ });
+
+ // If the longest phase was waiting for parallel tasks then record the
+ // longest task.
+ if (longest == PhaseKind::JOIN_PARALLEL_TASKS) {
+ PhaseKind longestParallel =
+ FindLongestPhaseKind(slice.maxParallelTimes);
+ reportLongestPhaseInMajorGC(longestParallel, [runtime](auto sample) {
+ runtime->metrics().GC_SLOW_TASK(sample);
+ });
+ }
+ }
+ }
+
+ // Record `wasLongSlice` for all TimeBudget slices.
+ runtime->metrics().GC_SLICE_WAS_LONG(wasLongSlice);
+ }
+}
+
+template <typename Fn>
+void Statistics::reportLongestPhaseInMajorGC(PhaseKind longest, Fn reportFn) {
+ if (longest != PhaseKind::NONE) {
+ uint8_t bucket = phaseKinds[longest].telemetryBucket;
+ reportFn(bucket);
+ }
+}
+
+bool Statistics::startTimingMutator() {
+ if (phaseStack.length() != 0) {
+ // Should only be called from outside of GC.
+ MOZ_ASSERT(phaseStack.length() == 1);
+ MOZ_ASSERT(phaseStack[0] == Phase::MUTATOR);
+ return false;
+ }
+
+ MOZ_ASSERT(suspendedPhases.empty());
+
+ timedGCTime = 0;
+ phaseStartTimes[Phase::MUTATOR] = TimeStamp();
+ phaseTimes[Phase::MUTATOR] = 0;
+ timedGCStart = TimeStamp();
+
+ beginPhase(PhaseKind::MUTATOR);
+ return true;
+}
+
+bool Statistics::stopTimingMutator(double& mutator_ms, double& gc_ms) {
+ // This should only be called from outside of GC, while timing the mutator.
+ if (phaseStack.length() != 1 || phaseStack[0] != Phase::MUTATOR) {
+ return false;
+ }
+
+ endPhase(PhaseKind::MUTATOR);
+ mutator_ms = t(phaseTimes[Phase::MUTATOR]);
+ gc_ms = t(timedGCTime);
+
+ return true;
+}
+
+void Statistics::suspendPhases(PhaseKind suspension) {
+ MOZ_ASSERT(suspension == PhaseKind::EXPLICIT_SUSPENSION ||
+ suspension == PhaseKind::IMPLICIT_SUSPENSION);
+ while (!phaseStack.empty()) {
+ MOZ_ASSERT(suspendedPhases.length() < MAX_SUSPENDED_PHASES);
+ Phase parent = phaseStack.back();
+ suspendedPhases.infallibleAppend(parent);
+ recordPhaseEnd(parent);
+ }
+ suspendedPhases.infallibleAppend(lookupChildPhase(suspension));
+}
+
+void Statistics::resumePhases() {
+ MOZ_ASSERT(suspendedPhases.back() == Phase::EXPLICIT_SUSPENSION ||
+ suspendedPhases.back() == Phase::IMPLICIT_SUSPENSION);
+ suspendedPhases.popBack();
+
+ while (!suspendedPhases.empty() &&
+ suspendedPhases.back() != Phase::EXPLICIT_SUSPENSION &&
+ suspendedPhases.back() != Phase::IMPLICIT_SUSPENSION) {
+ Phase resumePhase = suspendedPhases.popCopy();
+ if (resumePhase == Phase::MUTATOR) {
+ timedGCTime += TimeStamp::Now() - timedGCStart;
+ }
+ recordPhaseBegin(resumePhase);
+ }
+}
+
+void Statistics::beginPhase(PhaseKind phaseKind) {
+ // No longer timing these phases. We should never see these.
+ MOZ_ASSERT(phaseKind != PhaseKind::GC_BEGIN &&
+ phaseKind != PhaseKind::GC_END);
+
+ // PhaseKind::MUTATOR is suspended while performing GC.
+ if (currentPhase() == Phase::MUTATOR) {
+ suspendPhases(PhaseKind::IMPLICIT_SUSPENSION);
+ }
+
+ recordPhaseBegin(lookupChildPhase(phaseKind));
+}
+
+void Statistics::recordPhaseBegin(Phase phase) {
+ MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc->rt));
+
+ // Guard against any other re-entry.
+ MOZ_ASSERT(!phaseStartTimes[phase]);
+
+ MOZ_ASSERT(phaseStack.length() < MAX_PHASE_NESTING);
+
+ Phase current = currentPhase();
+ MOZ_ASSERT(phases[phase].parent == current);
+
+ TimeStamp now = TimeStamp::Now();
+
+ if (current != Phase::NONE) {
+ MOZ_ASSERT(now >= phaseStartTimes[currentPhase()],
+ "Inconsistent time data; see bug 1400153");
+ if (now < phaseStartTimes[currentPhase()]) {
+ now = phaseStartTimes[currentPhase()];
+ aborted = true;
+ }
+ }
+
+ phaseStack.infallibleAppend(phase);
+ phaseStartTimes[phase] = now;
+ log("begin: %s", phases[phase].path);
+}
+
+void Statistics::recordPhaseEnd(Phase phase) {
+ MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc->rt));
+
+ MOZ_ASSERT(phaseStartTimes[phase]);
+
+ TimeStamp now = TimeStamp::Now();
+
+ // Make sure this phase ends after it starts.
+ MOZ_ASSERT(now >= phaseStartTimes[phase],
+ "Inconsistent time data; see bug 1400153");
+
+#ifdef DEBUG
+ // Make sure this phase ends after all of its children. Note that some
+ // children might not have run in this instance, in which case they will
+ // have run in a previous instance of this parent or not at all.
+ for (Phase kid = phases[phase].firstChild; kid != Phase::NONE;
+ kid = phases[kid].nextSibling) {
+ if (phaseEndTimes[kid].IsNull()) {
+ continue;
+ }
+ if (phaseEndTimes[kid] > now) {
+ fprintf(stderr,
+ "Parent %s ended at %.3fms, before child %s ended at %.3fms?\n",
+ phases[phase].name, t(now - TimeStamp::FirstTimeStamp()),
+ phases[kid].name,
+ t(phaseEndTimes[kid] - TimeStamp::FirstTimeStamp()));
+ }
+ MOZ_ASSERT(phaseEndTimes[kid] <= now,
+ "Inconsistent time data; see bug 1400153");
+ }
+#endif
+
+ if (now < phaseStartTimes[phase]) {
+ now = phaseStartTimes[phase];
+ aborted = true;
+ }
+
+ if (phase == Phase::MUTATOR) {
+ timedGCStart = now;
+ }
+
+ phaseStack.popBack();
+
+ TimeDuration t = now - phaseStartTimes[phase];
+ if (!slices_.empty()) {
+ slices_.back().phaseTimes[phase] += t;
+ }
+ phaseTimes[phase] += t;
+ phaseStartTimes[phase] = TimeStamp();
+
+#ifdef DEBUG
+ phaseEndTimes[phase] = now;
+ log("end: %s", phases[phase].path);
+#endif
+}
+
+void Statistics::endPhase(PhaseKind phaseKind) {
+ Phase phase = currentPhase();
+ MOZ_ASSERT(phase != Phase::NONE);
+ MOZ_ASSERT(phases[phase].phaseKind == phaseKind);
+
+ recordPhaseEnd(phase);
+
+ // When emptying the stack, we may need to return to timing the mutator
+ // (PhaseKind::MUTATOR).
+ if (phaseStack.empty() && !suspendedPhases.empty() &&
+ suspendedPhases.back() == Phase::IMPLICIT_SUSPENSION) {
+ resumePhases();
+ }
+}
+
+void Statistics::recordParallelPhase(PhaseKind phaseKind,
+ TimeDuration duration) {
+ MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc->rt));
+
+ if (aborted) {
+ return;
+ }
+
+ slices_.back().totalParallelTimes[phaseKind] += duration;
+
+ // Also record the maximum task time for each phase. Don't record times for
+ // parent phases.
+ TimeDuration& maxTime = slices_.back().maxParallelTimes[phaseKind];
+ maxTime = std::max(maxTime, duration);
+}
+
+TimeStamp Statistics::beginSCC() { return TimeStamp::Now(); }
+
+void Statistics::endSCC(unsigned scc, TimeStamp start) {
+ if (scc >= sccTimes.length() && !sccTimes.resize(scc + 1)) {
+ return;
+ }
+
+ sccTimes[scc] += TimeStamp::Now() - start;
+}
+
+/*
+ * MMU (minimum mutator utilization) is a measure of how much garbage collection
+ * is affecting the responsiveness of the system. MMU measurements are given
+ * with respect to a certain window size. If we report MMU(50ms) = 80%, then
+ * that means that, for any 50ms window of time, at least 80% of the window is
+ * devoted to the mutator. In other words, the GC is running for at most 20% of
+ * the window, or 10ms. The GC can run multiple slices during the 50ms window
+ * as long as the total time it spends is at most 10ms.
+ */
+double Statistics::computeMMU(TimeDuration window) const {
+ MOZ_ASSERT(!slices_.empty());
+
+ TimeDuration gc = slices_[0].end - slices_[0].start;
+ TimeDuration gcMax = gc;
+
+ if (gc >= window) {
+ return 0.0;
+ }
+
+ int startIndex = 0;
+ for (size_t endIndex = 1; endIndex < slices_.length(); endIndex++) {
+ auto* startSlice = &slices_[startIndex];
+ auto& endSlice = slices_[endIndex];
+ gc += endSlice.end - endSlice.start;
+
+ while (endSlice.end - startSlice->end >= window) {
+ gc -= startSlice->end - startSlice->start;
+ startSlice = &slices_[++startIndex];
+ }
+
+ TimeDuration cur = gc;
+ if (endSlice.end - startSlice->start > window) {
+ cur -= (endSlice.end - startSlice->start - window);
+ }
+ if (cur > gcMax) {
+ gcMax = cur;
+ }
+ }
+
+ return double((window - gcMax) / window);
+}
+
+void Statistics::maybePrintProfileHeaders() {
+ static int printedHeader = 0;
+ if ((printedHeader++ % 200) == 0) {
+ printProfileHeader();
+ if (gc->nursery().enableProfiling()) {
+ gc->nursery().printProfileHeader();
+ }
+ }
+}
+
+// The following macros define GC profile metadata fields that are printed
+// before the timing information defined by FOR_EACH_GC_PROFILE_TIME.
+
+#define FOR_EACH_GC_PROFILE_COMMON_METADATA(_) \
+ _("PID", 7, "%7zu", pid) \
+ _("Runtime", 14, "0x%12p", runtime)
+
+#define FOR_EACH_GC_PROFILE_SLICE_METADATA(_) \
+ _("Timestamp", 10, "%10.6f", timestamp.ToSeconds()) \
+ _("Reason", 20, "%-20.20s", reason) \
+ _("States", 6, "%6s", formatGCStates(slice)) \
+ _("FSNR", 4, "%4s", formatGCFlags(slice)) \
+ _("SizeKB", 8, "%8zu", sizeKB) \
+ _("Budget", 6, "%6s", formatBudget(slice))
+
+#define FOR_EACH_GC_PROFILE_METADATA(_) \
+ FOR_EACH_GC_PROFILE_COMMON_METADATA(_) \
+ FOR_EACH_GC_PROFILE_SLICE_METADATA(_)
+
+void Statistics::printProfileHeader() {
+ if (!enableProfiling_) {
+ return;
+ }
+
+ Sprinter sprinter;
+ if (!sprinter.init() || !sprinter.put(MajorGCProfilePrefix)) {
+ return;
+ }
+
+#define PRINT_METADATA_NAME(name, width, _1, _2) \
+ if (!sprinter.jsprintf(" %-*s", width, name)) { \
+ return; \
+ }
+ FOR_EACH_GC_PROFILE_METADATA(PRINT_METADATA_NAME)
+#undef PRINT_METADATA_NAME
+
+#define PRINT_PROFILE_NAME(_1, text, _2) \
+ if (!sprinter.jsprintf(" %-6.6s", text)) { \
+ return; \
+ }
+ FOR_EACH_GC_PROFILE_TIME(PRINT_PROFILE_NAME)
+#undef PRINT_PROFILE_NAME
+
+ if (!sprinter.put("\n")) {
+ return;
+ }
+
+ fputs(sprinter.string(), profileFile());
+}
+
+static TimeDuration SumAllPhaseKinds(const Statistics::PhaseKindTimes& times) {
+ TimeDuration sum;
+ for (PhaseKind kind : AllPhaseKinds()) {
+ sum += times[kind];
+ }
+ return sum;
+}
+
+void Statistics::printSliceProfile() {
+ maybePrintProfileHeaders();
+
+ const SliceData& slice = slices_.back();
+ ProfileDurations times = getProfileTimes(slice);
+ updateTotalProfileTimes(times);
+
+ Sprinter sprinter;
+ if (!sprinter.init() || !sprinter.put(MajorGCProfilePrefix)) {
+ return;
+ }
+
+ size_t pid = getpid();
+ JSRuntime* runtime = gc->rt;
+ TimeDuration timestamp = slice.end - creationTime();
+ const char* reason = ExplainGCReason(slice.reason);
+ size_t sizeKB = gc->heapSize.bytes() / 1024;
+
+#define PRINT_FIELD_VALUE(_1, _2, format, value) \
+ if (!sprinter.jsprintf(" " format, value)) { \
+ return; \
+ }
+ FOR_EACH_GC_PROFILE_METADATA(PRINT_FIELD_VALUE)
+#undef PRINT_FIELD_VALUE
+
+ if (!printProfileTimes(times, sprinter)) {
+ return;
+ }
+
+ fputs(sprinter.string(), profileFile());
+}
+
+Statistics::ProfileDurations Statistics::getProfileTimes(
+ const SliceData& slice) const {
+ ProfileDurations times;
+
+ times[ProfileKey::Total] = slice.duration();
+ times[ProfileKey::Background] = SumAllPhaseKinds(slice.totalParallelTimes);
+
+#define GET_PROFILE_TIME(name, text, phase) \
+ if (phase != PhaseKind::NONE) { \
+ times[ProfileKey::name] = SumPhase(phase, slice.phaseTimes); \
+ }
+ FOR_EACH_GC_PROFILE_TIME(GET_PROFILE_TIME)
+#undef GET_PROFILE_TIME
+
+ return times;
+}
+
+void Statistics::updateTotalProfileTimes(const ProfileDurations& times) {
+#define UPDATE_PROFILE_TIME(name, _, phase) \
+ totalTimes_[ProfileKey::name] += times[ProfileKey::name];
+ FOR_EACH_GC_PROFILE_TIME(UPDATE_PROFILE_TIME)
+#undef UPDATE_PROFILE_TIME
+}
+
+const char* Statistics::formatGCStates(const SliceData& slice) {
+ DebugOnly<int> r =
+ SprintfLiteral(formatBuffer_, "%1d -> %1d", int(slice.initialState),
+ int(slice.finalState));
+ MOZ_ASSERT(r > 0 && r < FormatBufferLength);
+ return formatBuffer_;
+}
+
+const char* Statistics::formatGCFlags(const SliceData& slice) {
+ bool fullGC = gc->fullGCRequested;
+ bool shrinkingGC = gcOptions == JS::GCOptions::Shrink;
+ bool nonIncrementalGC = nonincrementalReason_ != GCAbortReason::None;
+ bool wasReset = slice.resetReason != GCAbortReason::None;
+
+ MOZ_ASSERT(FormatBufferLength >= 5);
+ formatBuffer_[0] = fullGC ? 'F' : ' ';
+ formatBuffer_[1] = shrinkingGC ? 'S' : ' ';
+ formatBuffer_[2] = nonIncrementalGC ? 'N' : ' ';
+ formatBuffer_[3] = wasReset ? 'R' : ' ';
+ formatBuffer_[4] = '\0';
+
+ return formatBuffer_;
+}
+
+const char* Statistics::formatBudget(const SliceData& slice) {
+ if (nonincrementalReason_ != GCAbortReason::None ||
+ !slice.budget.isTimeBudget()) {
+ formatBuffer_[0] = '\0';
+ return formatBuffer_;
+ }
+
+ DebugOnly<int> r =
+ SprintfLiteral(formatBuffer_, " %6" PRIi64, slice.budget.timeBudget());
+ MOZ_ASSERT(r > 0 && r < FormatBufferLength);
+ return formatBuffer_;
+}
+
+/* static */
+bool Statistics::printProfileTimes(const ProfileDurations& times,
+ Sprinter& sprinter) {
+ for (auto time : times) {
+ int64_t millis = int64_t(time.ToMilliseconds());
+ if (!sprinter.jsprintf(" %6" PRIi64, millis)) {
+ return false;
+ }
+ }
+
+ return sprinter.put("\n");
+}
+
+constexpr size_t SliceMetadataFormatWidth() {
+ size_t fieldCount = 0;
+ size_t totalWidth = 0;
+
+#define UPDATE_COUNT_AND_WIDTH(_1, width, _2, _3) \
+ fieldCount++; \
+ totalWidth += width;
+ FOR_EACH_GC_PROFILE_SLICE_METADATA(UPDATE_COUNT_AND_WIDTH)
+#undef UPDATE_COUNT_AND_WIDTH
+
+ // Add padding between fields.
+ totalWidth += fieldCount - 1;
+
+ return totalWidth;
+}
+
+void Statistics::printTotalProfileTimes() {
+ if (!enableProfiling_) {
+ return;
+ }
+
+ Sprinter sprinter;
+ if (!sprinter.init() || !sprinter.put(MajorGCProfilePrefix)) {
+ return;
+ }
+
+ size_t pid = getpid();
+ JSRuntime* runtime = gc->rt;
+
+#define PRINT_FIELD_VALUE(_1, _2, format, value) \
+ if (!sprinter.jsprintf(" " format, value)) { \
+ return; \
+ }
+ FOR_EACH_GC_PROFILE_COMMON_METADATA(PRINT_FIELD_VALUE)
+#undef PRINT_FIELD_VALUE
+
+ // Use whole width of per-slice metadata to print total slices so the profile
+ // totals that follow line up.
+ size_t width = SliceMetadataFormatWidth();
+ if (!sprinter.jsprintf(" %-*s", int(width), formatTotalSlices())) {
+ return;
+ }
+
+ if (!printProfileTimes(totalTimes_, sprinter)) {
+ return;
+ }
+
+ fputs(sprinter.string(), profileFile());
+}
+
+const char* Statistics::formatTotalSlices() {
+ DebugOnly<int> r = SprintfLiteral(
+ formatBuffer_, "TOTALS: %7" PRIu64 " slices:", sliceCount_);
+ MOZ_ASSERT(r > 0 && r < FormatBufferLength);
+ return formatBuffer_;
+}
generated by cgit v1.2.3 (git 2.39.1) at 2024-11-09 04:50:56 +0000