/* -*- 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; 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; }; // 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 }, { PHASE_GC_BEGIN, "Begin Callback", PHASE_NO_PARENT }, { PHASE_WAIT_BACKGROUND_THREAD, "Wait Background Thread", PHASE_NO_PARENT }, { PHASE_MARK_DISCARD_CODE, "Mark Discard Code", PHASE_NO_PARENT }, { PHASE_RELAZIFY_FUNCTIONS, "Relazify Functions", PHASE_NO_PARENT }, { PHASE_PURGE, "Purge", PHASE_NO_PARENT }, { PHASE_MARK, "Mark", PHASE_NO_PARENT }, { PHASE_UNMARK, "Unmark", PHASE_MARK }, /* PHASE_MARK_ROOTS */ { PHASE_MARK_DELAYED, "Mark Delayed", PHASE_MARK }, { PHASE_SWEEP, "Sweep", PHASE_NO_PARENT }, { PHASE_SWEEP_MARK, "Mark During Sweeping", PHASE_SWEEP }, { PHASE_SWEEP_MARK_TYPES, "Mark Types During Sweeping", PHASE_SWEEP_MARK }, { PHASE_SWEEP_MARK_INCOMING_BLACK, "Mark Incoming Black Pointers", PHASE_SWEEP_MARK }, { PHASE_SWEEP_MARK_WEAK, "Mark Weak", PHASE_SWEEP_MARK }, { PHASE_SWEEP_MARK_INCOMING_GRAY, "Mark Incoming Gray Pointers", PHASE_SWEEP_MARK }, { PHASE_SWEEP_MARK_GRAY, "Mark Gray", PHASE_SWEEP_MARK }, { PHASE_SWEEP_MARK_GRAY_WEAK, "Mark Gray and Weak", PHASE_SWEEP_MARK }, { PHASE_FINALIZE_START, "Finalize Start Callbacks", PHASE_SWEEP }, { PHASE_WEAK_ZONEGROUP_CALLBACK, "Per-Slice Weak Callback", PHASE_FINALIZE_START }, { PHASE_WEAK_COMPARTMENT_CALLBACK, "Per-Compartment Weak Callback", PHASE_FINALIZE_START }, { PHASE_SWEEP_ATOMS, "Sweep Atoms", PHASE_SWEEP }, { PHASE_SWEEP_SYMBOL_REGISTRY, "Sweep Symbol Registry", PHASE_SWEEP }, { PHASE_SWEEP_COMPARTMENTS, "Sweep Compartments", PHASE_SWEEP }, { PHASE_SWEEP_DISCARD_CODE, "Sweep Discard Code", PHASE_SWEEP_COMPARTMENTS }, { PHASE_SWEEP_INNER_VIEWS, "Sweep Inner Views", PHASE_SWEEP_COMPARTMENTS }, { PHASE_SWEEP_CC_WRAPPER, "Sweep Cross Compartment Wrappers", PHASE_SWEEP_COMPARTMENTS }, { PHASE_SWEEP_BASE_SHAPE, "Sweep Base Shapes", PHASE_SWEEP_COMPARTMENTS }, { PHASE_SWEEP_INITIAL_SHAPE, "Sweep Initial Shapes", PHASE_SWEEP_COMPARTMENTS }, { PHASE_SWEEP_TYPE_OBJECT, "Sweep Type Objects", PHASE_SWEEP_COMPARTMENTS }, { PHASE_SWEEP_BREAKPOINT, "Sweep Breakpoints", PHASE_SWEEP_COMPARTMENTS }, { PHASE_SWEEP_REGEXP, "Sweep Regexps", PHASE_SWEEP_COMPARTMENTS }, { PHASE_SWEEP_MISC, "Sweep Miscellaneous", PHASE_SWEEP_COMPARTMENTS }, { PHASE_SWEEP_TYPES, "Sweep type information", PHASE_SWEEP_COMPARTMENTS }, { PHASE_SWEEP_TYPES_BEGIN, "Sweep type tables and compilations", PHASE_SWEEP_TYPES }, { PHASE_SWEEP_TYPES_END, "Free type arena", PHASE_SWEEP_TYPES }, { PHASE_SWEEP_OBJECT, "Sweep Object", PHASE_SWEEP }, { PHASE_SWEEP_STRING, "Sweep String", PHASE_SWEEP }, { PHASE_SWEEP_SCRIPT, "Sweep Script", PHASE_SWEEP }, { PHASE_SWEEP_SCOPE, "Sweep Scope", PHASE_SWEEP }, { PHASE_SWEEP_SHAPE, "Sweep Shape", PHASE_SWEEP }, { PHASE_SWEEP_JITCODE, "Sweep JIT code", PHASE_SWEEP }, { PHASE_FINALIZE_END, "Finalize End Callback", PHASE_SWEEP }, { PHASE_DESTROY, "Deallocate", PHASE_SWEEP }, { PHASE_COMPACT, "Compact", PHASE_NO_PARENT }, { PHASE_COMPACT_MOVE, "Compact Move", PHASE_COMPACT }, { PHASE_COMPACT_UPDATE, "Compact Update", PHASE_COMPACT }, /* PHASE_MARK_ROOTS */ { PHASE_COMPACT_UPDATE_CELLS, "Compact Update Cells", PHASE_COMPACT_UPDATE }, { PHASE_GC_END, "End Callback", PHASE_NO_PARENT }, { PHASE_MINOR_GC, "All Minor GCs", PHASE_NO_PARENT }, /* PHASE_MARK_ROOTS */ { PHASE_EVICT_NURSERY, "Minor GCs to Evict Nursery", PHASE_NO_PARENT }, /* PHASE_MARK_ROOTS */ { PHASE_TRACE_HEAP, "Trace Heap", PHASE_NO_PARENT }, /* PHASE_MARK_ROOTS */ { PHASE_BARRIER, "Barriers", PHASE_NO_PARENT }, { PHASE_UNMARK_GRAY, "Unmark gray", PHASE_BARRIER }, { PHASE_MARK_ROOTS, "Mark Roots", PHASE_MULTI_PARENTS }, { PHASE_BUFFER_GRAY_ROOTS, "Buffer Gray Roots", PHASE_MARK_ROOTS }, { PHASE_MARK_CCWS, "Mark Cross Compartment Wrappers", PHASE_MARK_ROOTS }, { PHASE_MARK_STACK, "Mark C and JS stacks", PHASE_MARK_ROOTS }, { PHASE_MARK_RUNTIME_DATA, "Mark Runtime-wide Data", PHASE_MARK_ROOTS }, { PHASE_MARK_EMBEDDING, "Mark Embedding", PHASE_MARK_ROOTS }, { PHASE_MARK_COMPARTMENTS, "Mark Compartments", PHASE_MARK_ROOTS }, { PHASE_PURGE_SHAPE_TABLES, "Purge ShapeTables", PHASE_NO_PARENT }, { PHASE_LIMIT, nullptr, PHASE_NO_PARENT } }; 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() { // 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; } 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); 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; } // 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(); 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_); } }