summaryrefslogtreecommitdiffstats
path: root/js/src/gc/Statistics.cpp
diff options
context:
space:
mode:
Diffstat (limited to '')
-rw-r--r--js/src/gc/Statistics.cpp1633
1 files changed, 1633 insertions, 0 deletions
diff --git a/js/src/gc/Statistics.cpp b/js/src/gc/Statistics.cpp
new file mode 100644
index 0000000000..50cc055d18
--- /dev/null
+++ b/js/src/gc/Statistics.cpp
@@ -0,0 +1,1633 @@
+/* -*- 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 "debugger/DebugAPI.h"
+#include "gc/GC.h"
+#include "gc/Memory.h"
+#include "js/friend/UsageStatistics.h" // JS_TELEMETRY_*
+#include "util/Text.h"
+#include "vm/HelperThreads.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));
+}
+
+const char* js::gcstats::ExplainInvocationKind(JSGCInvocationKind gckind) {
+ MOZ_ASSERT(gckind == GC_NORMAL || gckind == GC_SHRINK);
+ if (gckind == GC_NORMAL) {
+ return "Normal";
+ } else {
+ return "Shrinking";
+ }
+}
+
+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* 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 {
+ 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) {
+ perror("opening log file");
+ MOZ_CRASH("Failed to open log file.");
+ }
+ }
+
+ return file;
+}
+
+struct PhaseKindInfo {
+ Phase firstPhase;
+ uint8_t telemetryBucket;
+};
+
+// 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;
+}
+
+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 %u not found under current phase kind %u",
+ unsigned(phaseKind), unsigned(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::PhaseTimeTable& 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], gckind == GC_SHRINK);
+ if (gckind == GC_SHRINK) {
+ SprintfLiteral(
+ buffer, "Kind: %s; Relocated: %.3f MiB; ",
+ ExplainInvocationKind(gckind),
+ double(ArenaSize * counts[COUNT_ARENA_RELOCATED]) / BYTES_PER_MB);
+ if (!fragments.append(DuplicateString(buffer))) {
+ return UniqueChars(nullptr);
+ }
+ }
+
+ return Join(fragments);
+}
+
+UniqueChars Statistics::formatCompactSlicePhaseTimes(
+ const PhaseTimeTable& 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, ExplainInvocationKind(gckind),
+ 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 PhaseTimeTable& 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);
+
+ formatJsonSlice(sliceNum, json);
+ return printer.release();
+}
+
+UniqueChars Statistics::renderNurseryJson() const {
+ Sprinter printer(nullptr, false);
+ if (!printer.init()) {
+ return UniqueChars(nullptr);
+ }
+ JSONPrinter json(printer);
+ 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::ProcessCreation();
+ 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);
+
+ 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));
+ 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 PhaseTimeTable& 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_(ReallyNow()),
+ allocsSinceMinorGC({0, 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");
+
+ const char* env = getenv("JS_GC_PROFILE");
+ if (env) {
+ if (0 == strcmp(env, "help")) {
+ fprintf(stderr,
+ "JS_GC_PROFILE=N\n"
+ "\tReport major GC's taking more than N milliseconds.\n");
+ exit(0);
+ }
+ enableProfiling_ = true;
+ profileThreshold_ = TimeDuration::FromMilliseconds(atoi(env));
+ }
+}
+
+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::PhaseTimeTable& 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::PhaseTimeTable& times,
+ const Statistics::PhaseTimeTable& 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;
+}
+
+using PhaseKindTimes =
+ EnumeratedArray<PhaseKind, PhaseKind::LIMIT, TimeDuration>;
+
+static PhaseKind FindLongestPhaseKind(const 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::PhaseTimeTable& times) {
+ // Start with total times per expanded phase, including children's times.
+ Statistics::PhaseTimeTable 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.
+ PhaseKindTimes phaseKindTimes;
+ for (auto i : AllPhaseKinds()) {
+ phaseKindTimes[i] = SumPhase(i, selfTimes);
+ }
+
+ return FindLongestPhaseKind(phaseKindTimes);
+}
+
+static TimeDuration PhaseMax(PhaseKind phaseKind,
+ const Statistics::PhaseTimeTable& times) {
+ TimeDuration max;
+ for (PhaseIter phase(phaseKind); !phase.done(); phase.next()) {
+ max = std::max(max, times[phase]);
+ }
+
+ return max;
+}
+
+static PhaseKind LongestParallelPhaseKind(
+ const Statistics::PhaseTimeTable& times) {
+ // Find longest time for each phase kind.
+ PhaseKindTimes phaseKindTimes;
+ for (auto i : AllPhaseKinds()) {
+ phaseKindTimes[i] = PhaseMax(i, times);
+ }
+
+ 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(JSGCInvocationKind kind,
+ const TimeStamp& currentTime) {
+ slices_.clearAndFree();
+ sccTimes.clearAndFree();
+ gckind = kind;
+ nonincrementalReason_ = GCAbortReason::None;
+
+ preTotalHeapBytes = gc->heapSize.bytes();
+
+ preCollectedHeapBytes = 0;
+
+ startingMajorGCNumber = gc->majorGCCount();
+ startingSliceNumber = gc->gcNumber();
+
+ if (gc->lastGCEndTime()) {
+ timeSinceLastGC = currentTime - gc->lastGCEndTime();
+ }
+}
+
+void Statistics::measureInitialHeapSize() {
+ MOZ_ASSERT(preCollectedHeapBytes == 0);
+ for (GCZonesIter zone(gc); !zone.done(); zone.next()) {
+ preCollectedHeapBytes += zone->gcHeapSize.bytes();
+ }
+}
+
+void Statistics::adoptHeapSizeDuringIncrementalGC(Zone* mergedZone) {
+ // A zone is being merged into a zone that's currently being collected so we
+ // need to adjust our record of the total size of heap for collected zones.
+ MOZ_ASSERT(gc->isIncrementalGCInProgress());
+ preCollectedHeapBytes += mergedZone->gcHeapSize.bytes();
+}
+
+void Statistics::endGC() {
+ postTotalHeapBytes = gc->heapSize.bytes();
+
+ sendGCTelemetry();
+}
+
+void Statistics::sendGCTelemetry() {
+ JSRuntime* runtime = gc->rt;
+ runtime->addTelemetry(JS_TELEMETRY_GC_IS_ZONE_GC,
+ !zoneStats.isFullCollection());
+ TimeDuration prepareTotal = SumPhase(PhaseKind::PREPARE, phaseTimes);
+ TimeDuration markTotal = SumPhase(PhaseKind::MARK, phaseTimes);
+ TimeDuration markRootsTotal = SumPhase(PhaseKind::MARK_ROOTS, phaseTimes);
+ TimeDuration markWeakTotal = phaseTimes[Phase::SWEEP_MARK_WEAK] +
+ phaseTimes[Phase::SWEEP_MARK_GRAY_WEAK];
+ TimeDuration markGrayTotal = phaseTimes[Phase::SWEEP_MARK_GRAY] +
+ phaseTimes[Phase::SWEEP_MARK_GRAY_WEAK];
+ size_t markCount = gc->marker.getMarkCount();
+ double markRate = markCount / t(markTotal);
+ runtime->addTelemetry(JS_TELEMETRY_GC_PREPARE_MS, t(prepareTotal));
+ runtime->addTelemetry(JS_TELEMETRY_GC_MARK_MS, t(markTotal));
+ runtime->addTelemetry(JS_TELEMETRY_GC_MARK_RATE_2, markRate);
+ runtime->addTelemetry(JS_TELEMETRY_GC_SWEEP_MS, t(phaseTimes[Phase::SWEEP]));
+ if (gc->didCompactZones()) {
+ runtime->addTelemetry(JS_TELEMETRY_GC_COMPACT_MS,
+ t(phaseTimes[Phase::COMPACT]));
+ }
+ runtime->addTelemetry(JS_TELEMETRY_GC_MARK_ROOTS_US,
+ markRootsTotal.ToMicroseconds());
+ runtime->addTelemetry(JS_TELEMETRY_GC_MARK_GRAY_MS_2, t(markGrayTotal));
+ runtime->addTelemetry(JS_TELEMETRY_GC_MARK_WEAK_MS, t(markWeakTotal));
+ runtime->addTelemetry(JS_TELEMETRY_GC_NON_INCREMENTAL, nonincremental());
+ if (nonincremental()) {
+ runtime->addTelemetry(JS_TELEMETRY_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->addTelemetry(JS_TELEMETRY_GC_RESET, lastSlice.wasReset());
+ if (lastSlice.wasReset()) {
+ runtime->addTelemetry(JS_TELEMETRY_GC_RESET_REASON,
+ uint32_t(lastSlice.resetReason));
+ }
+
+ TimeDuration total, longest;
+ gcDuration(&total, &longest);
+
+ runtime->addTelemetry(JS_TELEMETRY_GC_MS, t(total));
+ runtime->addTelemetry(JS_TELEMETRY_GC_MAX_PAUSE_MS_2, t(longest));
+
+ const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
+ runtime->addTelemetry(JS_TELEMETRY_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->addTelemetry(JS_TELEMETRY_GC_TIME_BETWEEN_S,
+ timeSinceLastGC.ToSeconds());
+ if (!nonincremental()) {
+ runtime->addTelemetry(JS_TELEMETRY_GC_SLICE_COUNT, slices_.length());
+ }
+ }
+
+ if (!lastSlice.wasReset()) {
+ 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 survialRate =
+ 100.0 * double(bytesSurvived) / double(preCollectedHeapBytes);
+ runtime->addTelemetry(JS_TELEMETRY_GC_TENURED_SURVIVAL_RATE,
+ uint32_t(survialRate));
+
+ // 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->addTelemetry(JS_TELEMETRY_GC_EFFECTIVENESS,
+ uint32_t(effectiveness));
+ }
+ }
+}
+
+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);
+ }
+
+ allocsSinceMinorGC = {0, 0};
+}
+
+Statistics::SliceData::SliceData(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,
+ JSGCInvocationKind gckind, SliceBudget budget,
+ JS::GCReason reason) {
+ MOZ_ASSERT(phaseStack.empty() ||
+ (phaseStack.length() == 1 && phaseStack[0] == Phase::MUTATOR));
+
+ this->zoneStats = zoneStats;
+
+ TimeStamp currentTime = ReallyNow();
+
+ bool first = !gc->isIncrementalGCInProgress();
+ if (first) {
+ beginGC(gckind, currentTime);
+ }
+
+ JSRuntime* runtime = gc->rt;
+ if (!runtime->parentRuntime && !slices_.empty()) {
+ TimeDuration timeSinceLastSlice = currentTime - slices_.back().end;
+ runtime->addTelemetry(JS_TELEMETRY_GC_TIME_BETWEEN_SLICES_MS,
+ uint32_t(timeSinceLastSlice.ToMilliseconds()));
+ }
+
+ 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->addTelemetry(JS_TELEMETRY_GC_REASON, uint32_t(reason));
+
+ // Slice callbacks should only fire for the outermost level.
+ bool wasFullGC = zoneStats.isFullCollection();
+ if (sliceCallback) {
+ JSContext* cx = context();
+ JS::GCDescription desc(!wasFullGC, false, gckind, 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 = ReallyNow();
+ slice.endFaults = GetPageFaultCount();
+ slice.finalState = gc->state();
+
+ log("end slice");
+
+ sendSliceTelemetry(slice);
+
+ sliceCount_++;
+ }
+
+ bool last = !gc->isIncrementalGCInProgress();
+ if (last) {
+ if (gcTimerFile) {
+ printStats();
+ }
+
+ if (!aborted) {
+ endGC();
+ }
+ }
+
+ if (enableProfiling_ && !aborted &&
+ slices_.back().duration() >= profileThreshold_) {
+ printSliceProfile();
+ }
+
+ // Slice callbacks should only fire for the outermost level.
+ if (!aborted) {
+ bool wasFullGC = zoneStats.isFullCollection();
+ if (sliceCallback) {
+ JSContext* cx = context();
+ JS::GCDescription desc(!wasFullGC, last, gckind, 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];
+
+ for (mozilla::TimeStamp& t : phaseStartTimes) {
+ t = TimeStamp();
+ }
+#ifdef DEBUG
+ for (mozilla::TimeStamp& t : phaseEndTimes) {
+ t = TimeStamp();
+ }
+#endif
+
+ for (TimeDuration& duration : phaseTimes) {
+ duration = TimeDuration();
+ MOZ_ASSERT(duration.IsZero());
+ }
+
+ 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->addTelemetry(JS_TELEMETRY_GC_SLICE_MS, t(sliceTime));
+
+ if (slice.budget.isTimeBudget()) {
+ int64_t budget_ms = slice.budget.timeBudget.budget;
+ runtime->addTelemetry(JS_TELEMETRY_GC_BUDGET_MS_2, budget_ms);
+ if (IsCurrentlyAnimating(runtime->lastAnimationTime, slice.end)) {
+ runtime->addTelemetry(JS_TELEMETRY_GC_ANIMATION_MS, t(sliceTime));
+ }
+
+ // Record any phase that goes 1.5 times or 5ms over its budget.
+ double longSliceThreshold = std::min(1.5 * budget_ms, budget_ms + 5.0);
+ if (sliceTime.ToMilliseconds() > longSliceThreshold) {
+ PhaseKind longest = LongestPhaseSelfTimeInMajorGC(slice.phaseTimes);
+ reportLongestPhaseInMajorGC(longest, JS_TELEMETRY_GC_SLOW_PHASE);
+
+ // If the longest phase was waiting for parallel tasks then record the
+ // longest task.
+ if (longest == PhaseKind::JOIN_PARALLEL_TASKS) {
+ PhaseKind longestParallel =
+ LongestParallelPhaseKind(slice.maxParallelTimes);
+ reportLongestPhaseInMajorGC(longestParallel, JS_TELEMETRY_GC_SLOW_TASK);
+ }
+ }
+
+ // Record how long we went over budget.
+ int64_t overrun = int64_t(sliceTime.ToMicroseconds()) - (1000 * budget_ms);
+ if (overrun > 0) {
+ runtime->addTelemetry(JS_TELEMETRY_GC_BUDGET_OVERRUN, uint32_t(overrun));
+ }
+ }
+}
+
+void Statistics::reportLongestPhaseInMajorGC(PhaseKind longest,
+ int telemetryId) {
+ JSRuntime* runtime = gc->rt;
+ if (longest != PhaseKind::NONE) {
+ uint8_t bucket = phaseKinds[longest].telemetryBucket;
+ runtime->addTelemetry(telemetryId, 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 += ReallyNow() - 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 = ReallyNow();
+
+ 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 = ReallyNow();
+
+ // 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::ProcessCreation()),
+ phases[kid].name,
+ t(phaseEndTimes[kid] - TimeStamp::ProcessCreation()));
+ }
+ 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;
+ }
+
+ // Record the maximum task time for each phase. Don't record times for parent
+ // phases.
+ Phase phase = lookupChildPhase(phaseKind);
+ TimeDuration& time = slices_.back().maxParallelTimes[phase];
+ time = std::max(time, duration);
+}
+
+TimeStamp Statistics::beginSCC() { return ReallyNow(); }
+
+void Statistics::endSCC(unsigned scc, TimeStamp start) {
+ if (scc >= sccTimes.length() && !sccTimes.resize(scc + 1)) {
+ return;
+ }
+
+ sccTimes[scc] += ReallyNow() - 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()) {
+ Nursery::printProfileHeader();
+ }
+ }
+}
+
+void Statistics::printProfileHeader() {
+ if (!enableProfiling_) {
+ return;
+ }
+
+ fprintf(stderr, "MajorGC: Timestamp Reason States FSNR ");
+ fprintf(stderr, " %6s", "budget");
+ fprintf(stderr, " %6s", "total");
+#define PRINT_PROFILE_HEADER(name, text, phase) fprintf(stderr, " %6s", text);
+ FOR_EACH_GC_PROFILE_TIME(PRINT_PROFILE_HEADER)
+#undef PRINT_PROFILE_HEADER
+ fprintf(stderr, "\n");
+}
+
+/* static */
+void Statistics::printProfileTimes(const ProfileDurations& times) {
+ for (auto time : times) {
+ fprintf(stderr, " %6" PRIi64, static_cast<int64_t>(time.ToMilliseconds()));
+ }
+ fprintf(stderr, "\n");
+}
+
+void Statistics::printSliceProfile() {
+ const SliceData& slice = slices_.back();
+
+ maybePrintProfileHeaders();
+
+ TimeDuration ts = slice.end - creationTime();
+
+ bool shrinking = gckind == GC_SHRINK;
+ bool reset = slice.resetReason != GCAbortReason::None;
+ bool nonIncremental = nonincrementalReason_ != GCAbortReason::None;
+ bool full = zoneStats.isFullCollection();
+
+ fprintf(stderr, "MajorGC: %10.6f %-20.20s %1d -> %1d %1s%1s%1s%1s ",
+ ts.ToSeconds(), ExplainGCReason(slice.reason),
+ int(slice.initialState), int(slice.finalState), full ? "F" : "",
+ shrinking ? "S" : "", nonIncremental ? "N" : "", reset ? "R" : "");
+
+ if (!nonIncremental && !slice.budget.isUnlimited() &&
+ slice.budget.isTimeBudget()) {
+ fprintf(stderr, " %6" PRIi64,
+ static_cast<int64_t>(slice.budget.timeBudget.budget));
+ } else {
+ fprintf(stderr, " ");
+ }
+
+ ProfileDurations times;
+ times[ProfileKey::Total] = slice.duration();
+ totalTimes_[ProfileKey::Total] += times[ProfileKey::Total];
+
+#define GET_PROFILE_TIME(name, text, phase) \
+ times[ProfileKey::name] = SumPhase(phase, slice.phaseTimes); \
+ totalTimes_[ProfileKey::name] += times[ProfileKey::name];
+ FOR_EACH_GC_PROFILE_TIME(GET_PROFILE_TIME)
+#undef GET_PROFILE_TIME
+
+ printProfileTimes(times);
+}
+
+void Statistics::printTotalProfileTimes() {
+ if (enableProfiling_) {
+ fprintf(stderr,
+ "MajorGC TOTALS: %7" PRIu64 " slices: ",
+ sliceCount_);
+ printProfileTimes(totalTimes_);
+ }
+}
generated by cgit v1.2.3 (git 2.39.1) at 2024-12-18 14:25:14 +0000