1290 lines
42 KiB
C++
1290 lines
42 KiB
C++
/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 4 -*-
|
|
* 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_);
|
|
}
|
|
}
|
|
|