diff options
Diffstat (limited to 'js/src/gc/Statistics.cpp')
| -rw-r--r-- | js/src/gc/Statistics.cpp | 1383 |
1 files changed, 1383 insertions, 0 deletions
diff --git a/js/src/gc/Statistics.cpp b/js/src/gc/Statistics.cpp new file mode 100644 index 000000000..19f9986dd --- /dev/null +++ b/js/src/gc/Statistics.cpp @@ -0,0 +1,1383 @@ +/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 4 -*- + * vim: set ts=8 sts=4 et sw=4 tw=99: + * 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/ArrayUtils.h" +#include "mozilla/DebugOnly.h" +#include "mozilla/IntegerRange.h" +#include "mozilla/PodOperations.h" +#include "mozilla/Sprintf.h" + +#include <ctype.h> +#include <stdarg.h> +#include <stdio.h> + +#include "jsprf.h" +#include "jsutil.h" + +#include "gc/Memory.h" +#include "vm/Debugger.h" +#include "vm/HelperThreads.h" +#include "vm/Runtime.h" +#include "vm/Time.h" + +using namespace js; +using namespace js::gc; +using namespace js::gcstats; + +using mozilla::DebugOnly; +using mozilla::MakeRange; +using mozilla::PodArrayZero; +using mozilla::PodZero; + +/* + * 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. + */ +JS_STATIC_ASSERT(JS::gcreason::NUM_TELEMETRY_REASONS >= JS::gcreason::NUM_REASONS); + +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::gcreason::ExplainReason(JS::gcreason::Reason reason) +{ + switch (reason) { +#define SWITCH_REASON(name) \ + case JS::gcreason::name: \ + return #name; + GCREASONS(SWITCH_REASON) + + default: + MOZ_CRASH("bad GC reason"); +#undef SWITCH_REASON + } +} + +const char* +js::gcstats::ExplainAbortReason(gc::AbortReason reason) +{ + switch (reason) { +#define SWITCH_REASON(name) \ + case gc::AbortReason::name: \ + return #name; + GC_ABORT_REASONS(SWITCH_REASON) + + default: + MOZ_CRASH("bad GC abort reason"); +#undef SWITCH_REASON + } +} + +static double +t(int64_t t) +{ + return double(t) / PRMJ_USEC_PER_MSEC; +} + +struct PhaseInfo +{ + Phase index; + const char* name; + Phase parent; + const uint8_t telemetryBucket; +}; + +// The zeroth entry in the timing arrays is used for phases that have a +// unique lineage. +static const size_t PHASE_DAG_NONE = 0; + +// These are really just fields of PhaseInfo, but I have to initialize them +// programmatically, which prevents making phases[] const. (And marking these +// fields mutable does not work on Windows; the whole thing gets created in +// read-only memory anyway.) +struct ExtraPhaseInfo +{ + // Depth in the tree of each phase type + size_t depth; + + // Index into the set of parallel arrays of timing data, for parents with + // at least one multi-parented child + size_t dagSlot; +}; + +static const Phase PHASE_NO_PARENT = PHASE_LIMIT; + +struct DagChildEdge { + Phase parent; + Phase child; +} dagChildEdges[] = { + { PHASE_MARK, PHASE_MARK_ROOTS }, + { PHASE_MINOR_GC, PHASE_MARK_ROOTS }, + { PHASE_TRACE_HEAP, PHASE_MARK_ROOTS }, + { PHASE_EVICT_NURSERY, PHASE_MARK_ROOTS }, + { PHASE_COMPACT_UPDATE, PHASE_MARK_ROOTS } +}; + +/* + * Note that PHASE_MUTATOR, PHASE_GC_BEGIN, and PHASE_GC_END never have any + * child phases. If beginPhase is called while one of these is active, they + * will automatically be suspended and resumed when the phase stack is next + * empty. Timings for these phases are thus exclusive of any other phase. + */ + +static const PhaseInfo phases[] = { + { PHASE_MUTATOR, "Mutator Running", PHASE_NO_PARENT, 0 }, + { PHASE_GC_BEGIN, "Begin Callback", PHASE_NO_PARENT, 1 }, + { PHASE_WAIT_BACKGROUND_THREAD, "Wait Background Thread", PHASE_NO_PARENT, 2 }, + { PHASE_MARK_DISCARD_CODE, "Mark Discard Code", PHASE_NO_PARENT, 3 }, + { PHASE_RELAZIFY_FUNCTIONS, "Relazify Functions", PHASE_NO_PARENT, 4 }, + { PHASE_PURGE, "Purge", PHASE_NO_PARENT, 5 }, + { PHASE_MARK, "Mark", PHASE_NO_PARENT, 6 }, + { PHASE_UNMARK, "Unmark", PHASE_MARK, 7 }, + /* PHASE_MARK_ROOTS */ + { PHASE_MARK_DELAYED, "Mark Delayed", PHASE_MARK, 8 }, + { PHASE_SWEEP, "Sweep", PHASE_NO_PARENT, 9 }, + { PHASE_SWEEP_MARK, "Mark During Sweeping", PHASE_SWEEP, 10 }, + { PHASE_SWEEP_MARK_TYPES, "Mark Types During Sweeping", PHASE_SWEEP_MARK, 11 }, + { PHASE_SWEEP_MARK_INCOMING_BLACK, "Mark Incoming Black Pointers", PHASE_SWEEP_MARK, 12 }, + { PHASE_SWEEP_MARK_WEAK, "Mark Weak", PHASE_SWEEP_MARK, 13 }, + { PHASE_SWEEP_MARK_INCOMING_GRAY, "Mark Incoming Gray Pointers", PHASE_SWEEP_MARK, 14 }, + { PHASE_SWEEP_MARK_GRAY, "Mark Gray", PHASE_SWEEP_MARK, 15 }, + { PHASE_SWEEP_MARK_GRAY_WEAK, "Mark Gray and Weak", PHASE_SWEEP_MARK, 16 }, + { PHASE_FINALIZE_START, "Finalize Start Callbacks", PHASE_SWEEP, 17 }, + { PHASE_WEAK_ZONEGROUP_CALLBACK, "Per-Slice Weak Callback", PHASE_FINALIZE_START, 57 }, + { PHASE_WEAK_COMPARTMENT_CALLBACK, "Per-Compartment Weak Callback", PHASE_FINALIZE_START, 58 }, + { PHASE_SWEEP_ATOMS, "Sweep Atoms", PHASE_SWEEP, 18 }, + { PHASE_SWEEP_SYMBOL_REGISTRY, "Sweep Symbol Registry", PHASE_SWEEP, 19 }, + { PHASE_SWEEP_COMPARTMENTS, "Sweep Compartments", PHASE_SWEEP, 20 }, + { PHASE_SWEEP_DISCARD_CODE, "Sweep Discard Code", PHASE_SWEEP_COMPARTMENTS, 21 }, + { PHASE_SWEEP_INNER_VIEWS, "Sweep Inner Views", PHASE_SWEEP_COMPARTMENTS, 22 }, + { PHASE_SWEEP_CC_WRAPPER, "Sweep Cross Compartment Wrappers", PHASE_SWEEP_COMPARTMENTS, 23 }, + { PHASE_SWEEP_BASE_SHAPE, "Sweep Base Shapes", PHASE_SWEEP_COMPARTMENTS, 24 }, + { PHASE_SWEEP_INITIAL_SHAPE, "Sweep Initial Shapes", PHASE_SWEEP_COMPARTMENTS, 25 }, + { PHASE_SWEEP_TYPE_OBJECT, "Sweep Type Objects", PHASE_SWEEP_COMPARTMENTS, 26 }, + { PHASE_SWEEP_BREAKPOINT, "Sweep Breakpoints", PHASE_SWEEP_COMPARTMENTS, 27 }, + { PHASE_SWEEP_REGEXP, "Sweep Regexps", PHASE_SWEEP_COMPARTMENTS, 28 }, + { PHASE_SWEEP_MISC, "Sweep Miscellaneous", PHASE_SWEEP_COMPARTMENTS, 29 }, + { PHASE_SWEEP_TYPES, "Sweep type information", PHASE_SWEEP_COMPARTMENTS, 30 }, + { PHASE_SWEEP_TYPES_BEGIN, "Sweep type tables and compilations", PHASE_SWEEP_TYPES, 31 }, + { PHASE_SWEEP_TYPES_END, "Free type arena", PHASE_SWEEP_TYPES, 32 }, + { PHASE_SWEEP_OBJECT, "Sweep Object", PHASE_SWEEP, 33 }, + { PHASE_SWEEP_STRING, "Sweep String", PHASE_SWEEP, 34 }, + { PHASE_SWEEP_SCRIPT, "Sweep Script", PHASE_SWEEP, 35 }, + { PHASE_SWEEP_SCOPE, "Sweep Scope", PHASE_SWEEP, 59 }, + { PHASE_SWEEP_SHAPE, "Sweep Shape", PHASE_SWEEP, 36 }, + { PHASE_SWEEP_JITCODE, "Sweep JIT code", PHASE_SWEEP, 37 }, + { PHASE_FINALIZE_END, "Finalize End Callback", PHASE_SWEEP, 38 }, + { PHASE_DESTROY, "Deallocate", PHASE_SWEEP, 39 }, + { PHASE_COMPACT, "Compact", PHASE_NO_PARENT, 40 }, + { PHASE_COMPACT_MOVE, "Compact Move", PHASE_COMPACT, 41 }, + { PHASE_COMPACT_UPDATE, "Compact Update", PHASE_COMPACT, 42 }, + /* PHASE_MARK_ROOTS */ + { PHASE_COMPACT_UPDATE_CELLS, "Compact Update Cells", PHASE_COMPACT_UPDATE, 43 }, + { PHASE_GC_END, "End Callback", PHASE_NO_PARENT, 44 }, + { PHASE_MINOR_GC, "All Minor GCs", PHASE_NO_PARENT, 45 }, + /* PHASE_MARK_ROOTS */ + { PHASE_EVICT_NURSERY, "Minor GCs to Evict Nursery", PHASE_NO_PARENT, 46 }, + /* PHASE_MARK_ROOTS */ + { PHASE_TRACE_HEAP, "Trace Heap", PHASE_NO_PARENT, 47 }, + /* PHASE_MARK_ROOTS */ + { PHASE_BARRIER, "Barriers", PHASE_NO_PARENT, 55 }, + { PHASE_UNMARK_GRAY, "Unmark gray", PHASE_BARRIER, 56 }, + { PHASE_MARK_ROOTS, "Mark Roots", PHASE_MULTI_PARENTS, 48 }, + { PHASE_BUFFER_GRAY_ROOTS, "Buffer Gray Roots", PHASE_MARK_ROOTS, 49 }, + { PHASE_MARK_CCWS, "Mark Cross Compartment Wrappers", PHASE_MARK_ROOTS, 50 }, + { PHASE_MARK_STACK, "Mark C and JS stacks", PHASE_MARK_ROOTS, 51 }, + { PHASE_MARK_RUNTIME_DATA, "Mark Runtime-wide Data", PHASE_MARK_ROOTS, 52 }, + { PHASE_MARK_EMBEDDING, "Mark Embedding", PHASE_MARK_ROOTS, 53 }, + { PHASE_MARK_COMPARTMENTS, "Mark Compartments", PHASE_MARK_ROOTS, 54 }, + { PHASE_PURGE_SHAPE_TABLES, "Purge ShapeTables", PHASE_NO_PARENT, 60 }, + + { PHASE_LIMIT, nullptr, PHASE_NO_PARENT, 60 } + + // Current number of telemetryBuckets is 60. If you insert new phases + // somewhere, start at that number and count up. Do not change any existing + // numbers. +}; + +static ExtraPhaseInfo phaseExtra[PHASE_LIMIT] = { { 0, 0 } }; + +// Mapping from all nodes with a multi-parented child to a Vector of all +// multi-parented children and their descendants. (Single-parented children will +// not show up in this list.) +static mozilla::Vector<Phase, 0, SystemAllocPolicy> dagDescendants[Statistics::NumTimingArrays]; + +// Preorder iterator over all phases in the expanded tree. Positions are +// returned as <phase,dagSlot> pairs (dagSlot will be zero aka PHASE_DAG_NONE +// for the top nodes with a single path from the parent, and 1 or more for +// nodes in multiparented subtrees). +struct AllPhaseIterator { + // If 'descendants' is empty, the current Phase position. + int current; + + // The depth of the current multiparented node that we are processing, or + // zero if we are pointing to the top portion of the tree. + int baseLevel; + + // When looking at multiparented descendants, the dag slot (index into + // PhaseTimeTables) containing the entries for the current parent. + size_t activeSlot; + + // When iterating over a multiparented subtree, the list of (remaining) + // subtree nodes. + mozilla::Vector<Phase, 0, SystemAllocPolicy>::Range descendants; + + explicit AllPhaseIterator(const Statistics::PhaseTimeTable table) + : current(0) + , baseLevel(0) + , activeSlot(PHASE_DAG_NONE) + , descendants(dagDescendants[PHASE_DAG_NONE].all()) /* empty range */ + { + } + + void get(Phase* phase, size_t* dagSlot, size_t* level = nullptr) { + MOZ_ASSERT(!done()); + *dagSlot = activeSlot; + *phase = descendants.empty() ? Phase(current) : descendants.front(); + if (level) + *level = phaseExtra[*phase].depth + baseLevel; + } + + void advance() { + MOZ_ASSERT(!done()); + + if (!descendants.empty()) { + // Currently iterating over a multiparented subtree. + descendants.popFront(); + if (!descendants.empty()) + return; + + // Just before leaving the last child, reset the iterator to look + // at "main" phases (in PHASE_DAG_NONE) instead of multiparented + // subtree phases. + ++current; + activeSlot = PHASE_DAG_NONE; + baseLevel = 0; + return; + } + + if (phaseExtra[current].dagSlot != PHASE_DAG_NONE) { + // The current phase has a shared subtree. Load them up into + // 'descendants' and advance to the first child. + activeSlot = phaseExtra[current].dagSlot; + descendants = dagDescendants[activeSlot].all(); + MOZ_ASSERT(!descendants.empty()); + baseLevel += phaseExtra[current].depth + 1; + return; + } + + ++current; + } + + bool done() const { + return phases[current].parent == PHASE_MULTI_PARENTS; + } +}; + +void +Statistics::gcDuration(int64_t* total, int64_t* maxPause) const +{ + *total = *maxPause = 0; + for (const SliceData* slice = slices.begin(); slice != slices.end(); slice++) { + *total += slice->duration(); + if (slice->duration() > *maxPause) + *maxPause = slice->duration(); + } + if (*maxPause > maxPauseInInterval) + maxPauseInInterval = *maxPause; +} + +void +Statistics::sccDurations(int64_t* total, int64_t* maxPause) +{ + *total = *maxPause = 0; + for (size_t i = 0; i < sccTimes.length(); i++) { + *total += sccTimes[i]; + *maxPause = 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); + 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 int64_t +SumChildTimes(size_t phaseSlot, Phase phase, const Statistics::PhaseTimeTable phaseTimes) +{ + // Sum the contributions from single-parented children. + int64_t total = 0; + size_t depth = phaseExtra[phase].depth; + for (unsigned i = phase + 1; i < PHASE_LIMIT && phaseExtra[i].depth > depth; i++) { + if (phases[i].parent == phase) + total += phaseTimes[phaseSlot][i]; + } + + // Sum the contributions from multi-parented children. + size_t dagSlot = phaseExtra[phase].dagSlot; + if (dagSlot != PHASE_DAG_NONE) { + for (auto edge : dagChildEdges) { + if (edge.parent == phase) + total += phaseTimes[dagSlot][edge.child]; + } + } + 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[index]; + + 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), + ExplainReason(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 +{ + const double bytesPerMiB = 1024 * 1024; + + FragmentVector fragments; + if (!fragments.append(DuplicateString("Summary - "))) + return UniqueChars(nullptr); + + int64_t total, longest; + gcDuration(&total, &longest); + + const double mmu20 = computeMMU(20 * PRMJ_USEC_PER_MSEC); + const double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC); + + 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 (%d); ", + zoneStats.collectedZoneCount, zoneStats.zoneCount, zoneStats.sweptZoneCount, + zoneStats.collectedCompartmentCount, zoneStats.compartmentCount, + zoneStats.sweptCompartmentCount, + double(preBytes) / bytesPerMiB, + counts[STAT_NEW_CHUNK] - counts[STAT_DESTROY_CHUNK], + counts[STAT_NEW_CHUNK] + counts[STAT_DESTROY_CHUNK]); + if (!fragments.append(DuplicateString(buffer))) + return UniqueChars(nullptr); + + MOZ_ASSERT_IF(counts[STAT_ARENA_RELOCATED], gckind == GC_SHRINK); + if (gckind == GC_SHRINK) { + SprintfLiteral(buffer, + "Kind: %s; Relocated: %.3f MiB; ", + ExplainInvocationKind(gckind), + double(ArenaSize * counts[STAT_ARENA_RELOCATED]) / bytesPerMiB); + if (!fragments.append(DuplicateString(buffer))) + return UniqueChars(nullptr); + } + + return Join(fragments); +} + +UniqueChars +Statistics::formatCompactSlicePhaseTimes(const PhaseTimeTable phaseTimes) const +{ + static const int64_t MaxUnaccountedTimeUS = 100; + + FragmentVector fragments; + char buffer[128]; + for (AllPhaseIterator iter(phaseTimes); !iter.done(); iter.advance()) { + Phase phase; + size_t dagSlot; + size_t level; + iter.get(&phase, &dagSlot, &level); + MOZ_ASSERT(level < 4); + + int64_t ownTime = phaseTimes[dagSlot][phase]; + int64_t childTime = SumChildTimes(dagSlot, phase, phaseTimes); + if (ownTime > MaxUnaccountedTimeUS) { + SprintfLiteral(buffer, "%s: %.3fms", phases[phase].name, t(ownTime)); + if (!fragments.append(DuplicateString(buffer))) + return UniqueChars(nullptr); + + if (childTime && (ownTime - childTime) > MaxUnaccountedTimeUS) { + 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() +{ + FragmentVector fragments; + + if (!fragments.append(formatDetailedDescription())) + return UniqueChars(nullptr); + + if (slices.length() > 1) { + 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 double bytesPerMiB = 1024 * 1024; + + int64_t sccTotal, sccLongest; + sccDurations(&sccTotal, &sccLongest); + + double mmu20 = computeMMU(20 * PRMJ_USEC_PER_MSEC); + double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC); + + 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), + ExplainReason(slices[0].reason), + nonincremental() ? "no - " : "yes", + nonincremental() ? ExplainAbortReason(nonincrementalReason_) : "", + zoneStats.collectedZoneCount, zoneStats.zoneCount, zoneStats.sweptZoneCount, + zoneStats.collectedCompartmentCount, zoneStats.compartmentCount, + zoneStats.sweptCompartmentCount, + counts[STAT_MINOR_GC], + counts[STAT_STOREBUFFER_OVERFLOW], + mmu20 * 100., mmu50 * 100., + t(sccTotal), t(sccLongest), + double(preBytes) / bytesPerMiB, + counts[STAT_NEW_CHUNK] - counts[STAT_DESTROY_CHUNK], + counts[STAT_NEW_CHUNK] + counts[STAT_DESTROY_CHUNK], + double(ArenaSize * counts[STAT_ARENA_RELOCATED]) / bytesPerMiB); + return DuplicateString(buffer); +} + +UniqueChars +Statistics::formatDetailedSliceDescription(unsigned i, const SliceData& slice) +{ + char budgetDescription[200]; + slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1); + + const char* format = +"\ + ---- Slice %u ----\n\ + Reason: %s\n\ + Reset: %s%s\n\ + State: %s -> %s\n\ + Page Faults: %ld\n\ + Pause: %.3fms of %s budget (@ %.3fms)\n\ +"; + char buffer[1024]; + SprintfLiteral(buffer, format, i, ExplainReason(slice.reason), + 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); +} + +UniqueChars +Statistics::formatDetailedPhaseTimes(const PhaseTimeTable phaseTimes) +{ + static const char* LevelToIndent[] = { "", " ", " ", " " }; + static const int64_t MaxUnaccountedChildTimeUS = 50; + + FragmentVector fragments; + char buffer[128]; + for (AllPhaseIterator iter(phaseTimes); !iter.done(); iter.advance()) { + Phase phase; + size_t dagSlot; + size_t level; + iter.get(&phase, &dagSlot, &level); + MOZ_ASSERT(level < 4); + + int64_t ownTime = phaseTimes[dagSlot][phase]; + int64_t childTime = SumChildTimes(dagSlot, phase, phaseTimes); + if (ownTime > 0) { + SprintfLiteral(buffer, " %s%s: %.3fms\n", + LevelToIndent[level], phases[phase].name, t(ownTime)); + if (!fragments.append(DuplicateString(buffer))) + return UniqueChars(nullptr); + + if (childTime && (ownTime - childTime) > MaxUnaccountedChildTimeUS) { + MOZ_ASSERT(level < 3); + SprintfLiteral(buffer, " %s%s: %.3fms\n", + LevelToIndent[level + 1], "Other", t(ownTime - childTime)); + if (!fragments.append(DuplicateString(buffer))) + return UniqueChars(nullptr); + } + } + } + return Join(fragments); +} + +UniqueChars +Statistics::formatDetailedTotals() +{ + int64_t 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); +} + +UniqueChars +Statistics::formatJsonMessage(uint64_t timestamp) +{ + MOZ_ASSERT(!aborted); + + FragmentVector fragments; + + if (!fragments.append(DuplicateString("{")) || + !fragments.append(formatJsonDescription(timestamp)) || + !fragments.append(DuplicateString("\"slices\":["))) + { + return UniqueChars(nullptr); + } + + for (unsigned i = 0; i < slices.length(); i++) { + if (!fragments.append(DuplicateString("{")) || + !fragments.append(formatJsonSliceDescription(i, slices[i])) || + !fragments.append(DuplicateString("\"times\":{")) || + !fragments.append(formatJsonPhaseTimes(slices[i].phaseTimes)) || + !fragments.append(DuplicateString("}}")) || + (i < (slices.length() - 1) && !fragments.append(DuplicateString(",")))) + { + return UniqueChars(nullptr); + } + } + + if (!fragments.append(DuplicateString("],\"totals\":{")) || + !fragments.append(formatJsonPhaseTimes(phaseTimes)) || + !fragments.append(DuplicateString("}}"))) + { + return UniqueChars(nullptr); + } + + return Join(fragments); +} + +UniqueChars +Statistics::formatJsonDescription(uint64_t timestamp) +{ + int64_t total, longest; + gcDuration(&total, &longest); + + int64_t sccTotal, sccLongest; + sccDurations(&sccTotal, &sccLongest); + + double mmu20 = computeMMU(20 * PRMJ_USEC_PER_MSEC); + double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC); + + const char *format = + "\"timestamp\":%llu," + "\"max_pause\":%llu.%03llu," + "\"total_time\":%llu.%03llu," + "\"zones_collected\":%d," + "\"total_zones\":%d," + "\"total_compartments\":%d," + "\"minor_gcs\":%d," + "\"store_buffer_overflows\":%d," + "\"mmu_20ms\":%d," + "\"mmu_50ms\":%d," + "\"scc_sweep_total\":%llu.%03llu," + "\"scc_sweep_max_pause\":%llu.%03llu," + "\"nonincremental_reason\":\"%s\"," + "\"allocated\":%u," + "\"added_chunks\":%d," + "\"removed_chunks\":%d,"; + char buffer[1024]; + SprintfLiteral(buffer, format, + (unsigned long long)timestamp, + longest / 1000, longest % 1000, + total / 1000, total % 1000, + zoneStats.collectedZoneCount, + zoneStats.zoneCount, + zoneStats.compartmentCount, + counts[STAT_MINOR_GC], + counts[STAT_STOREBUFFER_OVERFLOW], + int(mmu20 * 100), + int(mmu50 * 100), + sccTotal / 1000, sccTotal % 1000, + sccLongest / 1000, sccLongest % 1000, + ExplainAbortReason(nonincrementalReason_), + unsigned(preBytes / 1024 / 1024), + counts[STAT_NEW_CHUNK], + counts[STAT_DESTROY_CHUNK]); + return DuplicateString(buffer); +} + +UniqueChars +Statistics::formatJsonSliceDescription(unsigned i, const SliceData& slice) +{ + int64_t duration = slice.duration(); + int64_t when = slice.start - slices[0].start; + char budgetDescription[200]; + slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1); + int64_t pageFaults = slice.endFaults - slice.startFaults; + + const char* format = + "\"slice\":%d," + "\"pause\":%llu.%03llu," + "\"when\":%llu.%03llu," + "\"reason\":\"%s\"," + "\"initial_state\":\"%s\"," + "\"final_state\":\"%s\"," + "\"budget\":\"%s\"," + "\"page_faults\":%llu," + "\"start_timestamp\":%llu," + "\"end_timestamp\":%llu,"; + char buffer[1024]; + SprintfLiteral(buffer, format, + i, + duration / 1000, duration % 1000, + when / 1000, when % 1000, + ExplainReason(slice.reason), + gc::StateName(slice.initialState), + gc::StateName(slice.finalState), + budgetDescription, + pageFaults, + slice.start, + slice.end); + return DuplicateString(buffer); +} + +UniqueChars +FilterJsonKey(const char*const buffer) +{ + char* mut = strdup(buffer); + char* c = mut; + while (*c) { + if (!isalpha(*c)) + *c = '_'; + else if (isupper(*c)) + *c = tolower(*c); + ++c; + } + return UniqueChars(mut); +} + +UniqueChars +Statistics::formatJsonPhaseTimes(const PhaseTimeTable phaseTimes) +{ + FragmentVector fragments; + char buffer[128]; + for (AllPhaseIterator iter(phaseTimes); !iter.done(); iter.advance()) { + Phase phase; + size_t dagSlot; + iter.get(&phase, &dagSlot); + + UniqueChars name = FilterJsonKey(phases[phase].name); + int64_t ownTime = phaseTimes[dagSlot][phase]; + if (ownTime > 0) { + SprintfLiteral(buffer, "\"%s\":%" PRId64 ".%03" PRId64, + name.get(), ownTime / 1000, ownTime % 1000); + + if (!fragments.append(DuplicateString(buffer))) + return UniqueChars(nullptr); + } + } + return Join(fragments, ","); +} + +Statistics::Statistics(JSRuntime* rt) + : runtime(rt), + startupTime(PRMJ_Now()), + fp(nullptr), + gcDepth(0), + nonincrementalReason_(gc::AbortReason::None), + timedGCStart(0), + preBytes(0), + maxPauseInInterval(0), + phaseNestingDepth(0), + activeDagSlot(PHASE_DAG_NONE), + suspended(0), + sliceCallback(nullptr), + nurseryCollectionCallback(nullptr), + aborted(false), + enableProfiling_(false), + sliceCount_(0) +{ + PodArrayZero(phaseTotals); + PodArrayZero(counts); + PodArrayZero(phaseStartTimes); + for (auto d : MakeRange(NumTimingArrays)) + PodArrayZero(phaseTimes[d]); + + const char* env = getenv("MOZ_GCTIMER"); + if (env) { + if (strcmp(env, "none") == 0) { + fp = nullptr; + } else if (strcmp(env, "stdout") == 0) { + fp = stdout; + } else if (strcmp(env, "stderr") == 0) { + fp = stderr; + } else { + fp = fopen(env, "a"); + if (!fp) + MOZ_CRASH("Failed to open MOZ_GCTIMER log file."); + } + } + + 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_ = atoi(env); + } + + PodZero(&totalTimes_); +} + +Statistics::~Statistics() +{ + if (fp && fp != stdout && fp != stderr) + fclose(fp); +} + +/* static */ bool +Statistics::initialize() +{ + for (size_t i = 0; i < PHASE_LIMIT; i++) { + MOZ_ASSERT(phases[i].index == i); + for (size_t j = 0; j < PHASE_LIMIT; j++) + MOZ_ASSERT_IF(i != j, phases[i].telemetryBucket != phases[j].telemetryBucket); + } + + // Create a static table of descendants for every phase with multiple + // children. This assumes that all descendants come linearly in the + // list, which is reasonable since full dags are not supported; any + // path from the leaf to the root must encounter at most one node with + // multiple parents. + size_t dagSlot = 0; + for (size_t i = 0; i < mozilla::ArrayLength(dagChildEdges); i++) { + Phase parent = dagChildEdges[i].parent; + if (!phaseExtra[parent].dagSlot) + phaseExtra[parent].dagSlot = ++dagSlot; + + Phase child = dagChildEdges[i].child; + MOZ_ASSERT(phases[child].parent == PHASE_MULTI_PARENTS); + int j = child; + do { + if (!dagDescendants[phaseExtra[parent].dagSlot].append(Phase(j))) + return false; + j++; + } while (j != PHASE_LIMIT && phases[j].parent != PHASE_MULTI_PARENTS); + } + MOZ_ASSERT(dagSlot <= MaxMultiparentPhases - 1); + + // Fill in the depth of each node in the tree. Multi-parented nodes + // have depth 0. + mozilla::Vector<Phase, 0, SystemAllocPolicy> stack; + if (!stack.append(PHASE_LIMIT)) // Dummy entry to avoid special-casing the first node + return false; + for (int i = 0; i < PHASE_LIMIT; i++) { + if (phases[i].parent == PHASE_NO_PARENT || + phases[i].parent == PHASE_MULTI_PARENTS) + { + stack.clear(); + } else { + while (stack.back() != phases[i].parent) + stack.popBack(); + } + phaseExtra[i].depth = stack.length(); + if (!stack.append(Phase(i))) + return false; + } + + 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; +} + +int64_t +Statistics::clearMaxGCPauseAccumulator() +{ + int64_t prior = maxPauseInInterval; + maxPauseInInterval = 0; + return prior; +} + +int64_t +Statistics::getMaxGCPauseSinceClear() +{ + return maxPauseInInterval; +} + +// Sum up the time for a phase, including instances of the phase with different +// parents. +static int64_t +SumPhase(Phase phase, const Statistics::PhaseTimeTable times) +{ + int64_t sum = 0; + for (auto i : MakeRange(Statistics::NumTimingArrays)) + sum += times[i][phase]; + return sum; +} + +static Phase +LongestPhase(const Statistics::PhaseTimeTable times) +{ + int64_t longestTime = 0; + Phase longestPhase = PHASE_NONE; + for (size_t i = 0; i < PHASE_LIMIT; ++i) { + int64_t phaseTime = SumPhase(Phase(i), times); + if (phaseTime > longestTime) { + longestTime = phaseTime; + longestPhase = Phase(i); + } + } + return longestPhase; +} + +void +Statistics::printStats() +{ + if (aborted) { + fprintf(fp, "OOM during GC statistics collection. The report is unavailable for this GC.\n"); + } else { + UniqueChars msg = formatDetailedMessage(); + if (msg) + fprintf(fp, "GC(T+%.3fs) %s\n", t(slices[0].start - startupTime) / 1000.0, msg.get()); + } + fflush(fp); +} + +void +Statistics::beginGC(JSGCInvocationKind kind) +{ + slices.clearAndFree(); + sccTimes.clearAndFree(); + gckind = kind; + nonincrementalReason_ = gc::AbortReason::None; + + preBytes = runtime->gc.usage.gcBytes(); +} + +void +Statistics::endGC() +{ + for (auto j : MakeRange(NumTimingArrays)) + for (int i = 0; i < PHASE_LIMIT; i++) + phaseTotals[j][i] += phaseTimes[j][i]; + + int64_t total, longest; + gcDuration(&total, &longest); + + int64_t sccTotal, sccLongest; + sccDurations(&sccTotal, &sccLongest); + + runtime->addTelemetry(JS_TELEMETRY_GC_IS_ZONE_GC, !zoneStats.isCollectingAllZones()); + runtime->addTelemetry(JS_TELEMETRY_GC_MS, t(total)); + runtime->addTelemetry(JS_TELEMETRY_GC_MAX_PAUSE_MS, t(longest)); + int64_t markTotal = SumPhase(PHASE_MARK, phaseTimes); + int64_t markRootsTotal = SumPhase(PHASE_MARK_ROOTS, phaseTimes); + runtime->addTelemetry(JS_TELEMETRY_GC_MARK_MS, t(markTotal)); + runtime->addTelemetry(JS_TELEMETRY_GC_SWEEP_MS, t(phaseTimes[PHASE_DAG_NONE][PHASE_SWEEP])); + if (runtime->gc.isCompactingGc()) { + runtime->addTelemetry(JS_TELEMETRY_GC_COMPACT_MS, + t(phaseTimes[PHASE_DAG_NONE][PHASE_COMPACT])); + } + runtime->addTelemetry(JS_TELEMETRY_GC_MARK_ROOTS_MS, t(markRootsTotal)); + runtime->addTelemetry(JS_TELEMETRY_GC_MARK_GRAY_MS, t(phaseTimes[PHASE_DAG_NONE][PHASE_SWEEP_MARK_GRAY])); + runtime->addTelemetry(JS_TELEMETRY_GC_NON_INCREMENTAL, nonincremental()); + if (nonincremental()) + runtime->addTelemetry(JS_TELEMETRY_GC_NON_INCREMENTAL_REASON, uint32_t(nonincrementalReason_)); + runtime->addTelemetry(JS_TELEMETRY_GC_INCREMENTAL_DISABLED, !runtime->gc.isIncrementalGCAllowed()); + runtime->addTelemetry(JS_TELEMETRY_GC_SCC_SWEEP_TOTAL_MS, t(sccTotal)); + runtime->addTelemetry(JS_TELEMETRY_GC_SCC_SWEEP_MAX_PAUSE_MS, t(sccLongest)); + + if (!aborted) { + double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC); + runtime->addTelemetry(JS_TELEMETRY_GC_MMU_50, mmu50 * 100); + } + + if (fp) + printStats(); + + // Clear the OOM flag but only if we are not in a nested GC. + if (gcDepth == 1) + aborted = false; +} + +void +Statistics::beginNurseryCollection(JS::gcreason::Reason reason) +{ + count(STAT_MINOR_GC); + if (nurseryCollectionCallback) { + (*nurseryCollectionCallback)(runtime->contextFromMainThread(), + JS::GCNurseryProgress::GC_NURSERY_COLLECTION_START, + reason); + } +} + +void +Statistics::endNurseryCollection(JS::gcreason::Reason reason) +{ + if (nurseryCollectionCallback) { + (*nurseryCollectionCallback)(runtime->contextFromMainThread(), + JS::GCNurseryProgress::GC_NURSERY_COLLECTION_END, + reason); + } +} + +void +Statistics::beginSlice(const ZoneGCStats& zoneStats, JSGCInvocationKind gckind, + SliceBudget budget, JS::gcreason::Reason reason) +{ + gcDepth++; + this->zoneStats = zoneStats; + + bool first = !runtime->gc.isIncrementalGCInProgress(); + if (first) + beginGC(gckind); + + SliceData data(budget, reason, PRMJ_Now(), JS_GetCurrentEmbedderTime(), GetPageFaultCount(), + runtime->gc.state()); + if (!slices.append(data)) { + // If we are OOM, set a flag to indicate we have missing slice data. + aborted = true; + return; + } + + runtime->addTelemetry(JS_TELEMETRY_GC_REASON, reason); + + // Slice callbacks should only fire for the outermost level. + if (gcDepth == 1) { + bool wasFullGC = zoneStats.isCollectingAllZones(); + if (sliceCallback) + (*sliceCallback)(runtime->contextFromMainThread(), + first ? JS::GC_CYCLE_BEGIN : JS::GC_SLICE_BEGIN, + JS::GCDescription(!wasFullGC, gckind, reason)); + } +} + +void +Statistics::endSlice() +{ + if (!aborted) { + slices.back().end = PRMJ_Now(); + slices.back().endTimestamp = JS_GetCurrentEmbedderTime(); + slices.back().endFaults = GetPageFaultCount(); + slices.back().finalState = runtime->gc.state(); + + int64_t sliceTime = slices.back().end - slices.back().start; + runtime->addTelemetry(JS_TELEMETRY_GC_SLICE_MS, t(sliceTime)); + runtime->addTelemetry(JS_TELEMETRY_GC_RESET, slices.back().wasReset()); + if (slices.back().wasReset()) + runtime->addTelemetry(JS_TELEMETRY_GC_RESET_REASON, uint32_t(slices.back().resetReason)); + + if (slices.back().budget.isTimeBudget()) { + int64_t budget_ms = slices.back().budget.timeBudget.budget; + runtime->addTelemetry(JS_TELEMETRY_GC_BUDGET_MS, budget_ms); + if (budget_ms == runtime->gc.defaultSliceBudget()) + runtime->addTelemetry(JS_TELEMETRY_GC_ANIMATION_MS, t(sliceTime)); + + // Record any phase that goes more than 2x over its budget. + if (sliceTime > 2 * budget_ms * 1000) { + Phase longest = LongestPhase(slices.back().phaseTimes); + runtime->addTelemetry(JS_TELEMETRY_GC_SLOW_PHASE, phases[longest].telemetryBucket); + } + } + + sliceCount_++; + } + + bool last = !runtime->gc.isIncrementalGCInProgress(); + if (last) + endGC(); + + if (enableProfiling_ && !aborted && slices.back().duration() >= profileThreshold_) + printSliceProfile(); + + // Slice callbacks should only fire for the outermost level. + if (gcDepth == 1 && !aborted) { + bool wasFullGC = zoneStats.isCollectingAllZones(); + if (sliceCallback) + (*sliceCallback)(runtime->contextFromMainThread(), + last ? JS::GC_CYCLE_END : JS::GC_SLICE_END, + JS::GCDescription(!wasFullGC, gckind, slices.back().reason)); + } + + /* Do this after the slice callback since it uses these values. */ + if (last) { + PodArrayZero(counts); + + // Clear the timers at the end of a GC because we accumulate time in + // between GCs for some (which come before PHASE_GC_BEGIN in the list.) + PodZero(&phaseStartTimes[PHASE_GC_BEGIN], PHASE_LIMIT - PHASE_GC_BEGIN); + for (size_t d = PHASE_DAG_NONE; d < NumTimingArrays; d++) + PodZero(&phaseTimes[d][PHASE_GC_BEGIN], PHASE_LIMIT - PHASE_GC_BEGIN); + } + + gcDepth--; + MOZ_ASSERT(gcDepth >= 0); +} + +bool +Statistics::startTimingMutator() +{ + if (phaseNestingDepth != 0) { + // Should only be called from outside of GC. + MOZ_ASSERT(phaseNestingDepth == 1); + MOZ_ASSERT(phaseNesting[0] == PHASE_MUTATOR); + return false; + } + + MOZ_ASSERT(suspended == 0); + + timedGCTime = 0; + phaseStartTimes[PHASE_MUTATOR] = 0; + phaseTimes[PHASE_DAG_NONE][PHASE_MUTATOR] = 0; + timedGCStart = 0; + + beginPhase(PHASE_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 (phaseNestingDepth != 1 || phaseNesting[0] != PHASE_MUTATOR) + return false; + + endPhase(PHASE_MUTATOR); + mutator_ms = t(phaseTimes[PHASE_DAG_NONE][PHASE_MUTATOR]); + gc_ms = t(timedGCTime); + + return true; +} + +void +Statistics::suspendPhases(Phase suspension) +{ + MOZ_ASSERT(suspension == PHASE_EXPLICIT_SUSPENSION || suspension == PHASE_IMPLICIT_SUSPENSION); + while (phaseNestingDepth) { + MOZ_ASSERT(suspended < mozilla::ArrayLength(suspendedPhases)); + Phase parent = phaseNesting[phaseNestingDepth - 1]; + suspendedPhases[suspended++] = parent; + recordPhaseEnd(parent); + } + suspendedPhases[suspended++] = suspension; +} + +void +Statistics::resumePhases() +{ + DebugOnly<Phase> popped = suspendedPhases[--suspended]; + MOZ_ASSERT(popped == PHASE_EXPLICIT_SUSPENSION || popped == PHASE_IMPLICIT_SUSPENSION); + while (suspended && + suspendedPhases[suspended - 1] != PHASE_EXPLICIT_SUSPENSION && + suspendedPhases[suspended - 1] != PHASE_IMPLICIT_SUSPENSION) + { + Phase resumePhase = suspendedPhases[--suspended]; + if (resumePhase == PHASE_MUTATOR) + timedGCTime += PRMJ_Now() - timedGCStart; + beginPhase(resumePhase); + } +} + +void +Statistics::beginPhase(Phase phase) +{ + Phase parent = phaseNestingDepth ? phaseNesting[phaseNestingDepth - 1] : PHASE_NO_PARENT; + + // Re-entry is allowed during callbacks, so pause callback phases while + // other phases are in progress, auto-resuming after they end. As a result, + // nested GC time will not be accounted against the callback phases. + // + // Reuse this mechanism for managing PHASE_MUTATOR. + if (parent == PHASE_GC_BEGIN || parent == PHASE_GC_END || parent == PHASE_MUTATOR) { + suspendPhases(PHASE_IMPLICIT_SUSPENSION); + parent = phaseNestingDepth ? phaseNesting[phaseNestingDepth - 1] : PHASE_NO_PARENT; + } + + // Guard against any other re-entry. + MOZ_ASSERT(!phaseStartTimes[phase]); + + MOZ_ASSERT(phases[phase].index == phase); + MOZ_ASSERT(phaseNestingDepth < MAX_NESTING); + MOZ_ASSERT(phases[phase].parent == parent || phases[phase].parent == PHASE_MULTI_PARENTS); + + phaseNesting[phaseNestingDepth] = phase; + phaseNestingDepth++; + + if (phases[phase].parent == PHASE_MULTI_PARENTS) + activeDagSlot = phaseExtra[parent].dagSlot; + + phaseStartTimes[phase] = PRMJ_Now(); +} + +void +Statistics::recordPhaseEnd(Phase phase) +{ + int64_t now = PRMJ_Now(); + + if (phase == PHASE_MUTATOR) + timedGCStart = now; + + phaseNestingDepth--; + + int64_t t = now - phaseStartTimes[phase]; + if (!slices.empty()) + slices.back().phaseTimes[activeDagSlot][phase] += t; + phaseTimes[activeDagSlot][phase] += t; + phaseStartTimes[phase] = 0; +} + +void +Statistics::endPhase(Phase phase) +{ + recordPhaseEnd(phase); + + if (phases[phase].parent == PHASE_MULTI_PARENTS) + activeDagSlot = PHASE_DAG_NONE; + + // When emptying the stack, we may need to resume a callback phase + // (PHASE_GC_BEGIN/END) or return to timing the mutator (PHASE_MUTATOR). + if (phaseNestingDepth == 0 && suspended > 0 && suspendedPhases[suspended - 1] == PHASE_IMPLICIT_SUSPENSION) + resumePhases(); +} + +void +Statistics::endParallelPhase(Phase phase, const GCParallelTask* task) +{ + phaseNestingDepth--; + + if (!slices.empty()) + slices.back().phaseTimes[PHASE_DAG_NONE][phase] += task->duration(); + phaseTimes[PHASE_DAG_NONE][phase] += task->duration(); + phaseStartTimes[phase] = 0; +} + +int64_t +Statistics::beginSCC() +{ + return PRMJ_Now(); +} + +void +Statistics::endSCC(unsigned scc, int64_t start) +{ + if (scc >= sccTimes.length() && !sccTimes.resize(scc + 1)) + return; + + sccTimes[scc] += PRMJ_Now() - start; +} + +/* + * MMU (minimum mutator utilization) is a measure of how much garbage collection + * is affecting the responsiveness of the system. MMU measurements are given + * with respect to a certain window size. If we report MMU(50ms) = 80%, then + * that means that, for any 50ms window of time, at least 80% of the window is + * devoted to the mutator. In other words, the GC is running for at most 20% of + * the window, or 10ms. The GC can run multiple slices during the 50ms window + * as long as the total time it spends is at most 10ms. + */ +double +Statistics::computeMMU(int64_t window) const +{ + MOZ_ASSERT(!slices.empty()); + + int64_t gc = slices[0].end - slices[0].start; + int64_t gcMax = gc; + + if (gc >= window) + return 0.0; + + int startIndex = 0; + for (size_t endIndex = 1; endIndex < slices.length(); endIndex++) { + gc += slices[endIndex].end - slices[endIndex].start; + + while (slices[endIndex].end - slices[startIndex].end >= window) { + gc -= slices[startIndex].end - slices[startIndex].start; + startIndex++; + } + + int64_t cur = gc; + if (slices[endIndex].end - slices[startIndex].start > window) + cur -= (slices[endIndex].end - slices[startIndex].start - window); + if (cur > gcMax) + gcMax = cur; + } + + return double(window - gcMax) / window; +} + +/* static */ void +Statistics::printProfileHeader() +{ + 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 ProfileTimes& times) +{ + for (auto time : times) + fprintf(stderr, " %6" PRIi64, time / PRMJ_USEC_PER_MSEC); + fprintf(stderr, "\n"); +} + +void +Statistics::printSliceProfile() +{ + const SliceData& slice = slices.back(); + + static int printedHeader = 0; + if ((printedHeader++ % 200) == 0) { + fprintf(stderr, "MajorGC: Reason States "); + printProfileHeader(); + } + + fprintf(stderr, "MajorGC: %20s %1d -> %1d ", + ExplainReason(slice.reason), int(slice.initialState), int(slice.finalState)); + + ProfileTimes times; + times[ProfileKey::Total] = slice.duration(); + totalTimes_[ProfileKey::Total] += times[ProfileKey::Total]; + +#define GET_PROFILE_TIME(name, text, phase) \ + times[ProfileKey::name] = slice.phaseTimes[PHASE_DAG_NONE][phase]; \ + 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_); + } +} + |