diff options
author | Daniel Baumann <daniel.baumann@progress-linux.org> | 2024-04-28 14:29:10 +0000 |
---|---|---|
committer | Daniel Baumann <daniel.baumann@progress-linux.org> | 2024-04-28 14:29:10 +0000 |
commit | 2aa4a82499d4becd2284cdb482213d541b8804dd (patch) | |
tree | b80bf8bf13c3766139fbacc530efd0dd9d54394c /js/src/gc/Statistics.cpp | |
parent | Initial commit. (diff) | |
download | firefox-2aa4a82499d4becd2284cdb482213d541b8804dd.tar.xz firefox-2aa4a82499d4becd2284cdb482213d541b8804dd.zip |
Adding upstream version 86.0.1.upstream/86.0.1upstream
Signed-off-by: Daniel Baumann <daniel.baumann@progress-linux.org>
Diffstat (limited to 'js/src/gc/Statistics.cpp')
-rw-r--r-- | js/src/gc/Statistics.cpp | 1633 |
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_); + } +} |