Bug 1173354 - Switch GC statistics over to TimeStamp/TimeDuration, r=jonco

--HG--
extra : rebase_source : 6575a93731d2a26ca9b78c25a3dfa2aded5a108d
extra : histedit_source : df4b193445638710537524f4ddd8ac5cc183cb6b
This commit is contained in:
Steve Fink 2016-12-22 13:43:42 -08:00
Родитель 3360a85196
Коммит 17d54944b0
11 изменённых файлов: 177 добавлений и 162 удалений

Просмотреть файл

@ -7,6 +7,7 @@
#ifndef js_GCAPI_h
#define js_GCAPI_h
#include "mozilla/TimeStamp.h"
#include "mozilla/Vector.h"
#include "js/GCAnnotations.h"
@ -287,8 +288,8 @@ class GarbageCollectionEvent
// Represents a single slice of a possibly multi-slice incremental garbage
// collection.
struct Collection {
double startTimestamp;
double endTimestamp;
mozilla::TimeStamp startTimestamp;
mozilla::TimeStamp endTimestamp;
};
// The set of garbage collection slices that made up this GC cycle.

Просмотреть файл

@ -316,7 +316,7 @@ static bool
GetMaxGCPauseSinceClear(JSContext* cx, unsigned argc, Value* vp)
{
CallArgs args = CallArgsFromVp(argc, vp);
args.rval().setNumber(uint32_t(cx->runtime()->gc.stats.getMaxGCPauseSinceClear()));
args.rval().setNumber(cx->runtime()->gc.stats.getMaxGCPauseSinceClear().ToMicroseconds());
return true;
}
@ -324,7 +324,7 @@ static bool
ClearMaxGCPauseAccumulator(JSContext* cx, unsigned argc, Value* vp)
{
CallArgs args = CallArgsFromVp(argc, vp);
args.rval().setNumber(uint32_t(cx->runtime()->gc.stats.clearMaxGCPauseAccumulator()));
args.rval().setNumber(cx->runtime()->gc.stats.clearMaxGCPauseAccumulator().ToMicroseconds());
return true;
}

Просмотреть файл

@ -39,7 +39,8 @@ using namespace gc;
using mozilla::ArrayLength;
using mozilla::DebugOnly;
using mozilla::PodCopy;
using mozilla::PodZero;
using mozilla::TimeDuration;
using mozilla::TimeStamp;
static const uintptr_t CanaryMagicValue = 0xDEADB15D;
@ -165,7 +166,7 @@ js::Nursery::init(uint32_t maxNurseryBytes, AutoLockGC& lock)
exit(0);
}
enableProfiling_ = true;
profileThreshold_ = atoi(env);
profileThreshold_ = TimeDuration::FromMicroseconds(atoi(env));
}
env = getenv("JS_GC_REPORT_TENURING");
@ -178,10 +179,6 @@ js::Nursery::init(uint32_t maxNurseryBytes, AutoLockGC& lock)
reportTenurings_ = atoi(env);
}
PodZero(&startTimes_);
PodZero(&profileTimes_);
PodZero(&totalTimes_);
if (!runtime()->gc.storeBuffer.enable())
return false;
@ -503,10 +500,10 @@ FOR_EACH_NURSERY_PROFILE_TIME(PRINT_HEADER)
}
/* static */ void
js::Nursery::printProfileTimes(const ProfileTimes& times)
js::Nursery::printProfileDurations(const ProfileDurations& times)
{
for (auto time : times)
fprintf(stderr, " %6" PRIi64, time);
fprintf(stderr, " %6.0f", time.ToMicroseconds());
fprintf(stderr, "\n");
}
@ -515,21 +512,21 @@ js::Nursery::printTotalProfileTimes()
{
if (enableProfiling_) {
fprintf(stderr, "MinorGC TOTALS: %7" PRIu64 " collections: ", minorGcCount_);
printProfileTimes(totalTimes_);
printProfileDurations(totalDurations_);
}
}
inline void
js::Nursery::startProfile(ProfileKey key)
{
startTimes_[key] = PRMJ_Now();
startTimes_[key] = TimeStamp::Now();
}
inline void
js::Nursery::endProfile(ProfileKey key)
{
profileTimes_[key] = PRMJ_Now() - startTimes_[key];
totalTimes_[key] += profileTimes_[key];
profileDurations_[key] = TimeStamp::Now() - startTimes_[key];
totalDurations_[key] += profileDurations_[key];
}
inline void
@ -622,10 +619,10 @@ js::Nursery::collect(JSRuntime* rt, JS::gcreason::Reason reason)
endProfile(ProfileKey::Total);
minorGcCount_++;
int64_t totalTime = profileTimes_[ProfileKey::Total];
rt->addTelemetry(JS_TELEMETRY_GC_MINOR_US, totalTime);
TimeDuration totalTime = profileDurations_[ProfileKey::Total];
rt->addTelemetry(JS_TELEMETRY_GC_MINOR_US, totalTime.ToMicroseconds());
rt->addTelemetry(JS_TELEMETRY_GC_MINOR_REASON, reason);
if (totalTime > 1000)
if (totalTime.ToMilliseconds() > 1.0)
rt->addTelemetry(JS_TELEMETRY_GC_MINOR_REASON_LONG, reason);
rt->addTelemetry(JS_TELEMETRY_GC_NURSERY_BYTES, sizeOfHeapCommitted());
rt->addTelemetry(JS_TELEMETRY_GC_PRETENURE_COUNT, pretenureCount);
@ -640,7 +637,7 @@ js::Nursery::collect(JSRuntime* rt, JS::gcreason::Reason reason)
JS::gcreason::ExplainReason(reason),
promotionRate * 100,
numChunks());
printProfileTimes(profileTimes_);
printProfileDurations(profileDurations_);
if (reportTenurings_) {
for (auto& entry : tenureCounts.entries) {

Просмотреть файл

@ -9,6 +9,7 @@
#define gc_Nursery_h
#include "mozilla/EnumeratedArray.h"
#include "mozilla/TimeStamp.h"
#include "jsalloc.h"
#include "jspubtd.h"
@ -309,8 +310,8 @@ class Nursery
/* Promotion rate for the previous minor collection. */
double previousPromotionRate_;
/* Report minor collections taking at least this many us, if enabled. */
int64_t profileThreshold_;
/* Report minor collections taking at least this long, if enabled. */
mozilla::TimeDuration profileThreshold_;
bool enableProfiling_;
/* Report ObjectGroups with at lest this many instances tenured. */
@ -327,11 +328,14 @@ class Nursery
KeyCount
};
using ProfileTimes = mozilla::EnumeratedArray<ProfileKey, ProfileKey::KeyCount, int64_t>;
using ProfileTimes =
mozilla::EnumeratedArray<ProfileKey, ProfileKey::KeyCount, mozilla::TimeStamp>;
using ProfileDurations =
mozilla::EnumeratedArray<ProfileKey, ProfileKey::KeyCount, mozilla::TimeDuration>;
ProfileTimes startTimes_;
ProfileTimes profileTimes_;
ProfileTimes totalTimes_;
ProfileDurations profileDurations_;
ProfileDurations totalDurations_;
uint64_t minorGcCount_;
/*
@ -461,7 +465,7 @@ class Nursery
void endProfile(ProfileKey key);
void maybeStartProfile(ProfileKey key);
void maybeEndProfile(ProfileKey key);
static void printProfileTimes(const ProfileTimes& times);
static void printProfileDurations(const ProfileDurations& times);
friend class TenuringTracer;
friend class gc::MinorCollectionTracer;

Просмотреть файл

@ -11,6 +11,7 @@
#include "mozilla/IntegerRange.h"
#include "mozilla/PodOperations.h"
#include "mozilla/Sprintf.h"
#include "mozilla/TimeStamp.h"
#include <ctype.h>
#include <stdarg.h>
@ -33,6 +34,8 @@ using mozilla::DebugOnly;
using mozilla::MakeRange;
using mozilla::PodArrayZero;
using mozilla::PodZero;
using mozilla::TimeStamp;
using mozilla::TimeDuration;
/*
* If this fails, then you can either delete this assertion and allow all
@ -82,9 +85,9 @@ js::gcstats::ExplainAbortReason(gc::AbortReason reason)
}
static double
t(int64_t t)
t(TimeDuration duration)
{
return double(t) / PRMJ_USEC_PER_MSEC;
return duration.ToMilliseconds();
}
struct PhaseInfo
@ -288,7 +291,7 @@ struct AllPhaseIterator {
};
void
Statistics::gcDuration(int64_t* total, int64_t* maxPause) const
Statistics::gcDuration(TimeDuration* total, TimeDuration* maxPause) const
{
*total = *maxPause = 0;
for (const SliceData* slice = slices.begin(); slice != slices.end(); slice++) {
@ -301,7 +304,7 @@ Statistics::gcDuration(int64_t* total, int64_t* maxPause) const
}
void
Statistics::sccDurations(int64_t* total, int64_t* maxPause)
Statistics::sccDurations(TimeDuration* total, TimeDuration* maxPause)
{
*total = *maxPause = 0;
for (size_t i = 0; i < sccTimes.length(); i++) {
@ -340,11 +343,11 @@ Join(const FragmentVector& fragments, const char* separator = "") {
return UniqueChars(joined);
}
static int64_t
static TimeDuration
SumChildTimes(size_t phaseSlot, Phase phase, const Statistics::PhaseTimeTable phaseTimes)
{
// Sum the contributions from single-parented children.
int64_t total = 0;
TimeDuration 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)
@ -402,11 +405,11 @@ Statistics::formatCompactSummaryMessage() const
if (!fragments.append(DuplicateString("Summary - ")))
return UniqueChars(nullptr);
int64_t total, longest;
TimeDuration total, longest;
gcDuration(&total, &longest);
const double mmu20 = computeMMU(20 * PRMJ_USEC_PER_MSEC);
const double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
char buffer[1024];
if (!nonincremental()) {
@ -448,7 +451,7 @@ Statistics::formatCompactSummaryMessage() const
UniqueChars
Statistics::formatCompactSlicePhaseTimes(const PhaseTimeTable phaseTimes) const
{
static const int64_t MaxUnaccountedTimeUS = 100;
static const TimeDuration MaxUnaccountedTime = TimeDuration::FromMicroseconds(100);
FragmentVector fragments;
char buffer[128];
@ -459,14 +462,14 @@ Statistics::formatCompactSlicePhaseTimes(const PhaseTimeTable phaseTimes) const
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) {
TimeDuration ownTime = phaseTimes[dagSlot][phase];
TimeDuration childTime = SumChildTimes(dagSlot, phase, phaseTimes);
if (ownTime > MaxUnaccountedTime) {
SprintfLiteral(buffer, "%s: %.3fms", phases[phase].name, t(ownTime));
if (!fragments.append(DuplicateString(buffer)))
return UniqueChars(nullptr);
if (childTime && (ownTime - childTime) > MaxUnaccountedTimeUS) {
if (childTime && (ownTime - childTime) > MaxUnaccountedTime) {
MOZ_ASSERT(level < 3);
SprintfLiteral(buffer, "%s: %.3fms", "Other", t(ownTime - childTime));
if (!fragments.append(DuplicateString(buffer)))
@ -506,11 +509,11 @@ Statistics::formatDetailedDescription()
{
const double bytesPerMiB = 1024 * 1024;
int64_t sccTotal, sccLongest;
TimeDuration sccTotal, sccLongest;
sccDurations(&sccTotal, &sccLongest);
double mmu20 = computeMMU(20 * PRMJ_USEC_PER_MSEC);
double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
const char* format =
"=================================================================\n\
@ -576,7 +579,7 @@ UniqueChars
Statistics::formatDetailedPhaseTimes(const PhaseTimeTable phaseTimes)
{
static const char* LevelToIndent[] = { "", " ", " ", " " };
static const int64_t MaxUnaccountedChildTimeUS = 50;
static const TimeDuration MaxUnaccountedChildTime = TimeDuration::FromMicroseconds(50);
FragmentVector fragments;
char buffer[128];
@ -587,15 +590,15 @@ Statistics::formatDetailedPhaseTimes(const PhaseTimeTable phaseTimes)
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) {
TimeDuration ownTime = phaseTimes[dagSlot][phase];
TimeDuration childTime = SumChildTimes(dagSlot, phase, phaseTimes);
if (!ownTime.IsZero()) {
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) {
if (childTime && (ownTime - childTime) > MaxUnaccountedChildTime) {
MOZ_ASSERT(level < 3);
SprintfLiteral(buffer, " %s%s: %.3fms\n",
LevelToIndent[level + 1], "Other", t(ownTime - childTime));
@ -610,7 +613,7 @@ Statistics::formatDetailedPhaseTimes(const PhaseTimeTable phaseTimes)
UniqueChars
Statistics::formatDetailedTotals()
{
int64_t total, longest;
TimeDuration total, longest;
gcDuration(&total, &longest);
const char* format =
@ -663,19 +666,19 @@ Statistics::formatJsonMessage(uint64_t timestamp)
UniqueChars
Statistics::formatJsonDescription(uint64_t timestamp)
{
int64_t total, longest;
TimeDuration total, longest;
gcDuration(&total, &longest);
int64_t sccTotal, sccLongest;
TimeDuration sccTotal, sccLongest;
sccDurations(&sccTotal, &sccLongest);
double mmu20 = computeMMU(20 * PRMJ_USEC_PER_MSEC);
double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
const char *format =
"\"timestamp\":%llu,"
"\"max_pause\":%llu.%03llu,"
"\"total_time\":%llu.%03llu,"
"\"max_pause\":%.3f,"
"\"total_time\":%.3f,"
"\"zones_collected\":%d,"
"\"total_zones\":%d,"
"\"total_compartments\":%d,"
@ -683,8 +686,8 @@ Statistics::formatJsonDescription(uint64_t timestamp)
"\"store_buffer_overflows\":%d,"
"\"mmu_20ms\":%d,"
"\"mmu_50ms\":%d,"
"\"scc_sweep_total\":%llu.%03llu,"
"\"scc_sweep_max_pause\":%llu.%03llu,"
"\"scc_sweep_total\":%.3f,"
"\"scc_sweep_max_pause\":%.3f,"
"\"nonincremental_reason\":\"%s\","
"\"allocated\":%u,"
"\"added_chunks\":%d,"
@ -692,8 +695,8 @@ Statistics::formatJsonDescription(uint64_t timestamp)
char buffer[1024];
SprintfLiteral(buffer, format,
(unsigned long long)timestamp,
longest / 1000, longest % 1000,
total / 1000, total % 1000,
longest.ToMilliseconds(),
total.ToMilliseconds(),
zoneStats.collectedZoneCount,
zoneStats.zoneCount,
zoneStats.compartmentCount,
@ -701,8 +704,8 @@ Statistics::formatJsonDescription(uint64_t timestamp)
counts[STAT_STOREBUFFER_OVERFLOW],
int(mmu20 * 100),
int(mmu50 * 100),
sccTotal / 1000, sccTotal % 1000,
sccLongest / 1000, sccLongest % 1000,
sccTotal.ToMilliseconds(),
sccLongest.ToMilliseconds(),
ExplainAbortReason(nonincrementalReason_),
unsigned(preBytes / 1024 / 1024),
counts[STAT_NEW_CHUNK],
@ -713,35 +716,37 @@ Statistics::formatJsonDescription(uint64_t timestamp)
UniqueChars
Statistics::formatJsonSliceDescription(unsigned i, const SliceData& slice)
{
int64_t duration = slice.duration();
int64_t when = slice.start - slices[0].start;
TimeDuration duration = slice.duration();
TimeDuration when = slice.start - slices[0].start;
char budgetDescription[200];
slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
int64_t pageFaults = slice.endFaults - slice.startFaults;
bool ignore;
TimeStamp originTime = TimeStamp::ProcessCreation(ignore);
const char* format =
"\"slice\":%d,"
"\"pause\":%llu.%03llu,"
"\"when\":%llu.%03llu,"
"\"pause\":%.3f,"
"\"when\":%.3f,"
"\"reason\":\"%s\","
"\"initial_state\":\"%s\","
"\"final_state\":\"%s\","
"\"budget\":\"%s\","
"\"page_faults\":%llu,"
"\"start_timestamp\":%llu,"
"\"end_timestamp\":%llu,";
"\"start_timestamp\":%.3f,"
"\"end_timestamp\":%.3f,";
char buffer[1024];
SprintfLiteral(buffer, format,
i,
duration / 1000, duration % 1000,
when / 1000, when % 1000,
duration.ToMilliseconds(),
when.ToMilliseconds(),
ExplainReason(slice.reason),
gc::StateName(slice.initialState),
gc::StateName(slice.finalState),
budgetDescription,
pageFaults,
slice.start,
slice.end);
(slice.start - originTime).ToSeconds(),
(slice.end - originTime).ToSeconds());
return DuplicateString(buffer);
}
@ -771,10 +776,9 @@ Statistics::formatJsonPhaseTimes(const PhaseTimeTable phaseTimes)
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);
TimeDuration ownTime = phaseTimes[dagSlot][phase];
if (!ownTime.IsZero()) {
SprintfLiteral(buffer, "\"%s\":%.3f", name.get(), ownTime.ToMilliseconds());
if (!fragments.append(DuplicateString(buffer)))
return UniqueChars(nullptr);
@ -785,11 +789,9 @@ Statistics::formatJsonPhaseTimes(const PhaseTimeTable phaseTimes)
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),
@ -830,7 +832,7 @@ Statistics::Statistics(JSRuntime* rt)
exit(0);
}
enableProfiling_ = true;
profileThreshold_ = atoi(env);
profileThreshold_ = TimeDuration::FromMilliseconds(atoi(env));
}
PodZero(&totalTimes_);
@ -911,15 +913,15 @@ Statistics::setNurseryCollectionCallback(JS::GCNurseryCollectionCallback newCall
return oldCallback;
}
int64_t
TimeDuration
Statistics::clearMaxGCPauseAccumulator()
{
int64_t prior = maxPauseInInterval;
TimeDuration prior = maxPauseInInterval;
maxPauseInInterval = 0;
return prior;
}
int64_t
TimeDuration
Statistics::getMaxGCPauseSinceClear()
{
return maxPauseInInterval;
@ -927,33 +929,33 @@ Statistics::getMaxGCPauseSinceClear()
// Sum up the time for a phase, including instances of the phase with different
// parents.
static int64_t
static TimeDuration
SumPhase(Phase phase, const Statistics::PhaseTimeTable times)
{
int64_t sum = 0;
TimeDuration sum = 0;
for (auto i : MakeRange(Statistics::NumTimingArrays))
sum += times[i][phase];
return sum;
}
static void
CheckSelfTime(Phase parent, Phase child, const Statistics::PhaseTimeTable times, int64_t selfTimes[PHASE_LIMIT], int64_t childTime)
CheckSelfTime(Phase parent, Phase child, const Statistics::PhaseTimeTable times, TimeDuration selfTimes[PHASE_LIMIT], TimeDuration childTime)
{
if (selfTimes[parent] < childTime) {
fprintf(stderr,
"Parent %s time = %" PRId64
" with %" PRId64 " remaining, "
"child %s time %" PRId64 "\n",
phases[parent].name, SumPhase(parent, times),
selfTimes[parent],
phases[child].name, childTime);
"Parent %s time = %.3fms"
" with %.3fms remaining, "
"child %s time %.3fms\n",
phases[parent].name, SumPhase(parent, times).ToMilliseconds(),
selfTimes[parent].ToMilliseconds(),
phases[child].name, childTime.ToMilliseconds());
}
}
static Phase
LongestPhaseSelfTime(const Statistics::PhaseTimeTable times)
{
int64_t selfTimes[PHASE_LIMIT];
TimeDuration selfTimes[PHASE_LIMIT];
// Start with total times, including children's times.
for (size_t i = 0; i < PHASE_LIMIT; ++i)
@ -980,7 +982,7 @@ LongestPhaseSelfTime(const Statistics::PhaseTimeTable times)
}
}
int64_t longestTime = 0;
TimeDuration longestTime = 0;
Phase longestPhase = PHASE_NONE;
for (size_t i = 0; i < PHASE_LIMIT; ++i) {
if (selfTimes[i] > longestTime) {
@ -999,8 +1001,12 @@ Statistics::printStats()
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());
if (msg) {
bool ignoredInconsistency;
double secSinceStart =
(slices[0].start - TimeStamp::ProcessCreation(ignoredInconsistency)).ToSeconds();
fprintf(fp, "GC(T+%.3fs) %s\n", secSinceStart, msg.get());
}
}
fflush(fp);
}
@ -1023,17 +1029,17 @@ Statistics::endGC()
for (int i = 0; i < PHASE_LIMIT; i++)
phaseTotals[j][i] += phaseTimes[j][i];
int64_t total, longest;
TimeDuration total, longest;
gcDuration(&total, &longest);
int64_t sccTotal, sccLongest;
TimeDuration 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);
TimeDuration markTotal = SumPhase(PHASE_MARK, phaseTimes);
TimeDuration 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()) {
@ -1050,7 +1056,7 @@ Statistics::endGC()
runtime->addTelemetry(JS_TELEMETRY_GC_SCC_SWEEP_MAX_PAUSE_MS, t(sccLongest));
if (!aborted) {
double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
runtime->addTelemetry(JS_TELEMETRY_GC_MMU_50, mmu50 * 100);
}
@ -1094,8 +1100,7 @@ Statistics::beginSlice(const ZoneGCStats& zoneStats, JSGCInvocationKind gckind,
if (first)
beginGC(gckind);
SliceData data(budget, reason, PRMJ_Now(), JS_GetCurrentEmbedderTime(), GetPageFaultCount(),
runtime->gc.state());
SliceData data(budget, reason, TimeStamp::Now(), GetPageFaultCount(), runtime->gc.state());
if (!slices.append(data)) {
// If we are OOM, set a flag to indicate we have missing slice data.
aborted = true;
@ -1118,12 +1123,11 @@ void
Statistics::endSlice()
{
if (!aborted) {
slices.back().end = PRMJ_Now();
slices.back().endTimestamp = JS_GetCurrentEmbedderTime();
slices.back().end = TimeStamp::Now();
slices.back().endFaults = GetPageFaultCount();
slices.back().finalState = runtime->gc.state();
int64_t sliceTime = slices.back().end - slices.back().start;
TimeDuration 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())
@ -1136,7 +1140,7 @@ Statistics::endSlice()
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) {
if (sliceTime.ToMilliseconds() > 2 * budget_ms) {
Phase longest = LongestPhaseSelfTime(slices.back().phaseTimes);
runtime->addTelemetry(JS_TELEMETRY_GC_SLOW_PHASE, phases[longest].telemetryBucket);
}
@ -1189,9 +1193,9 @@ Statistics::startTimingMutator()
MOZ_ASSERT(suspended == 0);
timedGCTime = 0;
phaseStartTimes[PHASE_MUTATOR] = 0;
phaseStartTimes[PHASE_MUTATOR] = TimeStamp();
phaseTimes[PHASE_DAG_NONE][PHASE_MUTATOR] = 0;
timedGCStart = 0;
timedGCStart = TimeStamp();
beginPhase(PHASE_MUTATOR);
return true;
@ -1235,7 +1239,7 @@ Statistics::resumePhases()
{
Phase resumePhase = suspendedPhases[--suspended];
if (resumePhase == PHASE_MUTATOR)
timedGCTime += PRMJ_Now() - timedGCStart;
timedGCTime += TimeStamp::Now() - timedGCStart;
beginPhase(resumePhase);
}
}
@ -1268,24 +1272,24 @@ Statistics::beginPhase(Phase phase)
if (phases[phase].parent == PHASE_MULTI_PARENTS)
activeDagSlot = phaseExtra[parent].dagSlot;
phaseStartTimes[phase] = PRMJ_Now();
phaseStartTimes[phase] = TimeStamp::Now();
}
void
Statistics::recordPhaseEnd(Phase phase)
{
int64_t now = PRMJ_Now();
TimeStamp now = TimeStamp::Now();
if (phase == PHASE_MUTATOR)
timedGCStart = now;
phaseNestingDepth--;
int64_t t = now - phaseStartTimes[phase];
TimeDuration t = now - phaseStartTimes[phase];
if (!slices.empty())
slices.back().phaseTimes[activeDagSlot][phase] += t;
phaseTimes[activeDagSlot][phase] += t;
phaseStartTimes[phase] = 0;
phaseStartTimes[phase] = TimeStamp();
}
void
@ -1310,22 +1314,22 @@ Statistics::endParallelPhase(Phase phase, const GCParallelTask* task)
if (!slices.empty())
slices.back().phaseTimes[PHASE_DAG_NONE][phase] += task->duration();
phaseTimes[PHASE_DAG_NONE][phase] += task->duration();
phaseStartTimes[phase] = 0;
phaseStartTimes[phase] = TimeStamp();
}
int64_t
TimeStamp
Statistics::beginSCC()
{
return PRMJ_Now();
return TimeStamp::Now();
}
void
Statistics::endSCC(unsigned scc, int64_t start)
Statistics::endSCC(unsigned scc, TimeStamp start)
{
if (scc >= sccTimes.length() && !sccTimes.resize(scc + 1))
return;
sccTimes[scc] += PRMJ_Now() - start;
sccTimes[scc] += TimeStamp::Now() - start;
}
/*
@ -1338,12 +1342,12 @@ Statistics::endSCC(unsigned scc, int64_t start)
* as long as the total time it spends is at most 10ms.
*/
double
Statistics::computeMMU(int64_t window) const
Statistics::computeMMU(TimeDuration window) const
{
MOZ_ASSERT(!slices.empty());
int64_t gc = slices[0].end - slices[0].start;
int64_t gcMax = gc;
TimeDuration gc = slices[0].end - slices[0].start;
TimeDuration gcMax = gc;
if (gc >= window)
return 0.0;
@ -1357,14 +1361,14 @@ Statistics::computeMMU(int64_t window) const
startIndex++;
}
int64_t cur = gc;
TimeDuration 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;
return double((window - gcMax) / window);
}
void
@ -1393,10 +1397,10 @@ FOR_EACH_GC_PROFILE_TIME(PRINT_PROFILE_HEADER)
}
/* static */ void
Statistics::printProfileTimes(const ProfileTimes& times)
Statistics::printProfileTimes(const ProfileDurations& times)
{
for (auto time : times)
fprintf(stderr, " %6" PRIi64, time / PRMJ_USEC_PER_MSEC);
fprintf(stderr, " %6.0f", time.ToMilliseconds());
fprintf(stderr, "\n");
}
@ -1410,7 +1414,7 @@ Statistics::printSliceProfile()
fprintf(stderr, "MajorGC: %20s %1d -> %1d ",
ExplainReason(slice.reason), int(slice.initialState), int(slice.finalState));
ProfileTimes times;
ProfileDurations times;
times[ProfileKey::Total] = slice.duration();
totalTimes_[ProfileKey::Total] += times[ProfileKey::Total];

Просмотреть файл

@ -171,6 +171,9 @@ const char* ExplainInvocationKind(JSGCInvocationKind gckind);
*/
struct Statistics
{
using TimeDuration = mozilla::TimeDuration;
using TimeStamp = mozilla::TimeStamp;
/*
* Phases are allowed to have multiple parents, though any path from root
* to leaf is allowed at most one multi-parented phase. We keep a full set
@ -189,7 +192,7 @@ struct Statistics
static const size_t NumTimingArrays = MaxMultiparentPhases + 1;
/* Create a convenient type for referring to tables of phase times. */
using PhaseTimeTable = int64_t[NumTimingArrays][PHASE_LIMIT];
using PhaseTimeTable = TimeDuration[NumTimingArrays][PHASE_LIMIT];
static MOZ_MUST_USE bool initialize();
@ -254,8 +257,8 @@ struct Statistics
void beginNurseryCollection(JS::gcreason::Reason reason);
void endNurseryCollection(JS::gcreason::Reason reason);
int64_t beginSCC();
void endSCC(unsigned scc, int64_t start);
TimeStamp beginSCC();
void endSCC(unsigned scc, TimeStamp start);
UniqueChars formatCompactSliceMessage() const;
UniqueChars formatCompactSummaryMessage() const;
@ -266,8 +269,8 @@ struct Statistics
JS::GCNurseryCollectionCallback setNurseryCollectionCallback(
JS::GCNurseryCollectionCallback callback);
int64_t clearMaxGCPauseAccumulator();
int64_t getMaxGCPauseSinceClear();
TimeDuration clearMaxGCPauseAccumulator();
TimeDuration getMaxGCPauseSinceClear();
// Return the current phase, suppressing the synthetic PHASE_MUTATOR phase.
Phase currentPhase() {
@ -281,13 +284,13 @@ struct Statistics
static const size_t MAX_NESTING = 20;
struct SliceData {
SliceData(SliceBudget budget, JS::gcreason::Reason reason, int64_t start,
double startTimestamp, size_t startFaults, gc::State initialState)
SliceData(SliceBudget budget, JS::gcreason::Reason reason,
TimeStamp start, size_t startFaults, gc::State initialState)
: budget(budget), reason(reason),
initialState(initialState),
finalState(gc::State::NotActive),
resetReason(gc::AbortReason::None),
start(start), startTimestamp(startTimestamp),
start(start),
startFaults(startFaults)
{
for (auto i : mozilla::MakeRange(NumTimingArrays))
@ -298,12 +301,11 @@ struct Statistics
JS::gcreason::Reason reason;
gc::State initialState, finalState;
gc::AbortReason resetReason;
int64_t start, end;
double startTimestamp, endTimestamp;
TimeStamp start, end;
size_t startFaults, endFaults;
PhaseTimeTable phaseTimes;
int64_t duration() const { return end - start; }
TimeDuration duration() const { return end - start; }
bool wasReset() const { return resetReason != gc::AbortReason::None; }
};
@ -325,8 +327,6 @@ struct Statistics
private:
JSRuntime* runtime;
int64_t startupTime;
/* File pointer used for MOZ_GCTIMER output. */
FILE* fp;
@ -345,11 +345,11 @@ struct Statistics
SliceDataVector slices;
/* Most recent time when the given phase started. */
int64_t phaseStartTimes[PHASE_LIMIT];
TimeStamp phaseStartTimes[PHASE_LIMIT];
/* Bookkeeping for GC timings when timingMutator is true */
int64_t timedGCStart;
int64_t timedGCTime;
TimeStamp timedGCStart;
TimeDuration timedGCTime;
/* Total time in a given phase for this GC. */
PhaseTimeTable phaseTimes;
@ -364,7 +364,7 @@ struct Statistics
size_t preBytes;
/* Records the maximum GC pause in an API-controlled interval (in us). */
mutable int64_t maxPauseInInterval;
mutable TimeDuration maxPauseInInterval;
/* Phases that are currently on stack. */
Phase phaseNesting[MAX_NESTING];
@ -382,7 +382,7 @@ struct Statistics
size_t suspended;
/* Sweep times for SCCs of compartments. */
Vector<int64_t, 0, SystemAllocPolicy> sccTimes;
Vector<TimeDuration, 0, SystemAllocPolicy> sccTimes;
JS::GCSliceCallback sliceCallback;
JS::GCNurseryCollectionCallback nurseryCollectionCallback;
@ -405,11 +405,12 @@ FOR_EACH_GC_PROFILE_TIME(DEFINE_TIME_KEY)
KeyCount
};
using ProfileTimes = mozilla::EnumeratedArray<ProfileKey, ProfileKey::KeyCount, int64_t>;
using ProfileDurations =
mozilla::EnumeratedArray<ProfileKey, ProfileKey::KeyCount, TimeDuration>;
int64_t profileThreshold_;
TimeDuration profileThreshold_;
bool enableProfiling_;
ProfileTimes totalTimes_;
ProfileDurations totalTimes_;
uint64_t sliceCount_;
void beginGC(JSGCInvocationKind kind);
@ -417,8 +418,8 @@ FOR_EACH_GC_PROFILE_TIME(DEFINE_TIME_KEY)
void recordPhaseEnd(Phase phase);
void gcDuration(int64_t* total, int64_t* maxPause) const;
void sccDurations(int64_t* total, int64_t* maxPause);
void gcDuration(TimeDuration* total, TimeDuration* maxPause) const;
void sccDurations(TimeDuration* total, TimeDuration* maxPause);
void printStats();
UniqueChars formatCompactSlicePhaseTimes(const PhaseTimeTable phaseTimes) const;
@ -432,10 +433,10 @@ FOR_EACH_GC_PROFILE_TIME(DEFINE_TIME_KEY)
UniqueChars formatJsonSliceDescription(unsigned i, const SliceData& slice);
UniqueChars formatJsonPhaseTimes(const PhaseTimeTable phaseTimes);
double computeMMU(int64_t resolution) const;
double computeMMU(TimeDuration resolution) const;
void printSliceProfile();
static void printProfileTimes(const ProfileTimes& times);
static void printProfileTimes(const ProfileDurations& times);
};
struct MOZ_RAII AutoGCSlice
@ -502,7 +503,7 @@ struct MOZ_RAII AutoSCC
Statistics& stats;
unsigned scc;
int64_t start;
mozilla::TimeStamp start;
};
} /* namespace gcstats */

Просмотреть файл

@ -2,6 +2,7 @@
* 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 "mozilla/TimeStamp.h"
#include "mozilla/UniquePtr.h"
#include "js/GCAPI.h"

Просмотреть файл

@ -189,6 +189,7 @@
#include "mozilla/MemoryReporting.h"
#include "mozilla/Move.h"
#include "mozilla/ScopeExit.h"
#include "mozilla/TimeStamp.h"
#include <ctype.h>
#include <string.h>

Просмотреть файл

@ -12,6 +12,7 @@
#include "mozilla/Atomics.h"
#include "mozilla/EnumeratedArray.h"
#include "mozilla/MemoryReporting.h"
#include "mozilla/TimeStamp.h"
#include "mozilla/TypeTraits.h"
#include "js/GCAPI.h"
@ -947,7 +948,7 @@ class GCParallelTask
} state;
// Amount of time this task took to execute.
uint64_t duration_;
mozilla::TimeDuration duration_;
explicit GCParallelTask(const GCParallelTask&) = delete;
@ -970,7 +971,7 @@ class GCParallelTask
virtual ~GCParallelTask();
// Time spent in the most recent invocation of this task.
int64_t duration() const { return duration_; }
mozilla::TimeDuration duration() const { return duration_; }
// The simple interface to a parallel task works exactly like pthreads.
bool start();

Просмотреть файл

@ -61,6 +61,8 @@ using mozilla::Some;
using mozilla::Nothing;
using mozilla::Variant;
using mozilla::AsVariant;
using mozilla::TimeDuration;
using mozilla::TimeStamp;
/*** Forward declarations, ClassOps and Classes **************************************************/
@ -11237,11 +11239,10 @@ GarbageCollectionEvent::Create(JSRuntime* rt, ::js::gcstats::Statistics& stats,
if (!data->collections.growBy(1))
return nullptr;
data->collections.back().startTimestamp = range.front().startTimestamp;
data->collections.back().endTimestamp = range.front().endTimestamp;
data->collections.back().startTimestamp = range.front().start;
data->collections.back().endTimestamp = range.front().end;
}
return data;
}
@ -11275,14 +11276,18 @@ GarbageCollectionEvent::toJSObject(JSContext* cx) const
if (!slicesArray)
return nullptr;
bool ignored; // Ignore inconsistencies in process creation timestamp.
TimeStamp originTime = TimeStamp::ProcessCreation(ignored);
size_t idx = 0;
for (auto range = collections.all(); !range.empty(); range.popFront()) {
RootedPlainObject collectionObj(cx, NewBuiltinClassInstance<PlainObject>(cx));
if (!collectionObj)
return nullptr;
RootedValue start(cx, NumberValue(range.front().startTimestamp));
RootedValue end(cx, NumberValue(range.front().endTimestamp));
RootedValue start(cx), end(cx);
start = NumberValue((range.front().startTimestamp - originTime).ToMilliseconds());
end = NumberValue((range.front().endTimestamp - originTime).ToMilliseconds());
if (!DefineProperty(cx, collectionObj, cx->names().startTimestamp, start) ||
!DefineProperty(cx, collectionObj, cx->names().endTimestamp, end))
{

Просмотреть файл

@ -1142,9 +1142,9 @@ js::GCParallelTask::runFromMainThread(JSRuntime* rt)
{
MOZ_ASSERT(state == NotStarted);
MOZ_ASSERT(js::CurrentThreadCanAccessRuntime(rt));
uint64_t timeStart = PRMJ_Now();
mozilla::TimeStamp timeStart = mozilla::TimeStamp::Now();
run();
duration_ = PRMJ_Now() - timeStart;
duration_ = mozilla::TimeStamp::Now() - timeStart;
}
void
@ -1153,9 +1153,9 @@ js::GCParallelTask::runFromHelperThread(AutoLockHelperThreadState& locked)
{
AutoUnlockHelperThreadState parallelSection(locked);
gc::AutoSetThreadIsPerformingGC performingGC;
uint64_t timeStart = PRMJ_Now();
mozilla::TimeStamp timeStart = mozilla::TimeStamp::Now();
run();
duration_ = PRMJ_Now() - timeStart;
duration_ = mozilla::TimeStamp::Now() - timeStart;
}
state = Finished;