Magic-Mirror/gecko-dev
1
0
Fork 0
mirror of https://github.com/mozilla/gecko-dev.git synced 2024-10-10 03:45:46 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

Bug 1322560 - Add APIs for retrieving major GC timing info, r=jonco

Browse Source 
--HG--
extra : rebase_source : 9a038e2b7ea4c0d6242eed9ab6d753e590619bdb
extra : source : 4dee851a0d45655260ace1c01eb4dd9e9905942f
This commit is contained in:
Steve Fink 2017-05-02 15:45:43 -07:00
parent bebca54180
commit 350af64f4a
5 changed files with 155 additions and 74 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

9
js/public/GCAPI.h
View File

@ -13,6 +13,7 @@
#include "js/GCAnnotations.h"
#include "js/HeapAPI.h"
#include "js/UniquePtr.h"
#include "js/Utility.h"
namespace js {
namespace gc {
@ -345,6 +346,14 @@ struct JS_PUBLIC_API(GCDescription) {
char16_t* formatSummaryMessage(JSContext* cx) const;
char16_t* formatJSON(JSContext* cx, uint64_t timestamp) const;
mozilla::TimeStamp startTime(JSContext* cx) const;
mozilla::TimeStamp endTime(JSContext* cx) const;
mozilla::TimeStamp lastSliceStart(JSContext* cx) const;
mozilla::TimeStamp lastSliceEnd(JSContext* cx) const;
JS::UniqueChars sliceToJSON(JSContext* cx) const;
JS::UniqueChars summaryToJSON(JSContext* cx) const;
JS::dbg::GarbageCollectionEvent::Ptr toGCEvent(JSContext* cx) const;
};

152
js/src/gc/Statistics.cpp
View File

@ -308,10 +308,10 @@ void
Statistics::gcDuration(TimeDuration* total, TimeDuration* 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();
for (auto& slice : slices_) {
*total += slice.duration();
if (slice.duration() > *maxPause)
*maxPause = slice.duration();
}
if (*maxPause > maxPauseInInterval)
maxPauseInInterval = *maxPause;
@ -384,11 +384,11 @@ UniqueChars
Statistics::formatCompactSliceMessage() const
{
// Skip if we OOM'ed.
if (slices.length() == 0)
if (slices_.length() == 0)
return UniqueChars(nullptr);
const size_t index = slices.length() - 1;
const SliceData& slice = slices[index];
const size_t index = slices_.length() - 1;
const SliceData& slice = slices_.back();
char budgetDescription[200];
slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
@ -397,14 +397,14 @@ Statistics::formatCompactSliceMessage() const
"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),
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)))
!fragments.append(formatCompactSlicePhaseTimes(slices_[index].phaseTimes)))
{
return UniqueChars(nullptr);
}
@ -503,11 +503,11 @@ Statistics::formatDetailedMessage() const
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])))
if (!slices_.empty()) {
for (unsigned i = 0; i < slices_.length(); i++) {
if (!fragments.append(formatDetailedSliceDescription(i, slices_[i])))
return UniqueChars(nullptr);
if (!fragments.append(formatDetailedPhaseTimes(slices[i].phaseTimes)))
if (!fragments.append(formatDetailedPhaseTimes(slices_[i].phaseTimes)))
return UniqueChars(nullptr);
}
}
@ -548,7 +548,7 @@ Statistics::formatDetailedDescription() const
char buffer[1024];
SprintfLiteral(buffer, format,
ExplainInvocationKind(gckind),
ExplainReason(slices[0].reason),
ExplainReason(slices_[0].reason),
nonincremental() ? "no - " : "yes",
nonincremental() ? ExplainAbortReason(nonincrementalReason_) : "",
zoneStats.collectedZoneCount, zoneStats.zoneCount, zoneStats.sweptZoneCount,
@ -586,7 +586,7 @@ Statistics::formatDetailedSliceDescription(unsigned i, const SliceData& slice) c
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));
t(slice.duration()), budgetDescription, t(slice.start - slices_[0].start));
return DuplicateString(buffer);
}
@ -643,32 +643,52 @@ Statistics::formatDetailedTotals() const
}
UniqueChars
Statistics::formatJsonMessage(uint64_t timestamp) const
Statistics::formatJsonSlice(size_t sliceNum) const
{
MOZ_ASSERT(!aborted);
FragmentVector fragments;
if (!fragments.append(DuplicateString("{")) ||
!fragments.append(formatJsonDescription(timestamp)) ||
!fragments.append(DuplicateString("\"slices\":[")))
!fragments.append(formatJsonSliceDescription(sliceNum, slices_[sliceNum])) ||
!fragments.append(DuplicateString("\"times\":{")) ||
!fragments.append(formatJsonPhaseTimes(slices_[sliceNum].phaseTimes)) ||
!fragments.append(DuplicateString("}}")))
{
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);
}
return Join(fragments);
}
UniqueChars
Statistics::formatJsonMessage(uint64_t timestamp, bool includeSlices) const
{
if (aborted)
return DuplicateString("{status:\"aborted\"}"); // May return nullptr
FragmentVector fragments;
if (!fragments.append(DuplicateString("{")) ||
!fragments.append(formatJsonDescription(timestamp)))
{
return UniqueChars(nullptr);
}
if (!fragments.append(DuplicateString("],\"totals\":{")) ||
if (includeSlices) {
if (!fragments.append(DuplicateString("\"slices\":[")))
return UniqueChars(nullptr);
for (unsigned i = 0; i < slices_.length(); i++) {
if (!fragments.append(formatJsonSlice(i)))
return UniqueChars(nullptr);
if ((i < (slices_.length() - 1) && !fragments.append(DuplicateString(","))))
return UniqueChars(nullptr);
}
if (!fragments.append(DuplicateString("],")))
return UniqueChars(nullptr);
}
if (!fragments.append(DuplicateString("\"totals\":{")) ||
!fragments.append(formatJsonPhaseTimes(phaseTimes)) ||
!fragments.append(DuplicateString("}}")))
{
@ -708,6 +728,7 @@ Statistics::formatJsonDescription(uint64_t timestamp) const
"\"timestamp\":%llu,"
"\"max_pause\":%llu.%03llu,"
"\"total_time\":%llu.%03llu,"
"\"reason\":\"%s\","
"\"zones_collected\":%d,"
"\"total_zones\":%d,"
"\"total_compartments\":%d,"
@ -726,6 +747,7 @@ Statistics::formatJsonDescription(uint64_t timestamp) const
(unsigned long long)timestamp,
longestParts.quot, longestParts.rem,
totalParts.quot, totalParts.rem,
ExplainReason(slices_[0].reason),
zoneStats.collectedZoneCount,
zoneStats.zoneCount,
zoneStats.compartmentCount,
@ -747,7 +769,7 @@ Statistics::formatJsonSliceDescription(unsigned i, const SliceData& slice) const
{
TimeDuration duration = slice.duration();
lldiv_t durationParts = SplitDurationMS(duration);
TimeDuration when = slice.start - slices[0].start;
TimeDuration when = slice.start - slices_[0].start;
lldiv_t whenParts = SplitDurationMS(when);
char budgetDescription[200];
slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
@ -1034,7 +1056,7 @@ Statistics::printStats()
UniqueChars msg = formatDetailedMessage();
if (msg) {
double secSinceStart =
(slices[0].start - TimeStamp::ProcessCreation()).ToSeconds();
(slices_[0].start - TimeStamp::ProcessCreation()).ToSeconds();
fprintf(fp, "GC(T+%.3fs) %s\n", secSinceStart, msg.get());
}
}
@ -1044,7 +1066,7 @@ Statistics::printStats()
void
Statistics::beginGC(JSGCInvocationKind kind)
{
slices.clearAndFree();
slices_.clearAndFree();
sccTimes.clearAndFree();
gckind = kind;
nonincrementalReason_ = gc::AbortReason::None;
@ -1130,11 +1152,11 @@ Statistics::beginSlice(const ZoneGCStats& zoneStats, JSGCInvocationKind gckind,
if (first)
beginGC(gckind);
if (!slices.emplaceBack(budget,
reason,
TimeStamp::Now(),
GetPageFaultCount(),
runtime->gc.state()))
if (!slices_.emplaceBack(budget,
reason,
TimeStamp::Now(),
GetPageFaultCount(),
runtime->gc.state()))
{
// If we are OOM, set a flag to indicate we have missing slice data.
aborted = true;
@ -1155,25 +1177,25 @@ void
Statistics::endSlice()
{
if (!aborted) {
slices.back().end = TimeStamp::Now();
slices.back().endFaults = GetPageFaultCount();
slices.back().finalState = runtime->gc.state();
slices_.back().end = TimeStamp::Now();
slices_.back().endFaults = GetPageFaultCount();
slices_.back().finalState = runtime->gc.state();
TimeDuration 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())
runtime->addTelemetry(JS_TELEMETRY_GC_RESET_REASON, uint32_t(slices.back().resetReason));
runtime->addTelemetry(JS_TELEMETRY_GC_RESET, slices_.back().wasReset());
if (slices_.back().wasReset())
runtime->addTelemetry(JS_TELEMETRY_GC_RESET_REASON, uint32_t(slices_.back().resetReason));
if (slices.back().budget.isTimeBudget()) {
int64_t budget_ms = slices.back().budget.timeBudget.budget;
if (slices_.back().budget.isTimeBudget()) {
int64_t budget_ms = slices_.back().budget.timeBudget.budget;
runtime->addTelemetry(JS_TELEMETRY_GC_BUDGET_MS, budget_ms);
if (budget_ms == runtime->gc.defaultSliceBudget())
runtime->addTelemetry(JS_TELEMETRY_GC_ANIMATION_MS, t(sliceTime));
// Record any phase that goes more than 2x over its budget.
if (sliceTime.ToMilliseconds() > 2 * budget_ms) {
Phase longest = LongestPhaseSelfTime(slices.back().phaseTimes);
Phase longest = LongestPhaseSelfTime(slices_.back().phaseTimes);
runtime->addTelemetry(JS_TELEMETRY_GC_SLOW_PHASE, phases[longest].telemetryBucket);
}
}
@ -1185,7 +1207,7 @@ Statistics::endSlice()
if (last)
endGC();
if (enableProfiling_ && !aborted && slices.back().duration() >= profileThreshold_)
if (enableProfiling_ && !aborted && slices_.back().duration() >= profileThreshold_)
printSliceProfile();
// Slice callbacks should only fire for the outermost level.
@ -1194,7 +1216,7 @@ Statistics::endSlice()
if (sliceCallback)
(*sliceCallback)(TlsContext.get(),
last ? JS::GC_CYCLE_END : JS::GC_SLICE_END,
JS::GCDescription(!wasFullGC, gckind, slices.back().reason));
JS::GCDescription(!wasFullGC, gckind, slices_.back().reason));
}
// Do this after the slice callback since it uses these values.
@ -1318,8 +1340,8 @@ Statistics::recordPhaseEnd(Phase phase)
phaseNestingDepth--;
TimeDuration t = now - phaseStartTimes[phase];
if (!slices.empty())
slices.back().phaseTimes[activeDagSlot][phase] += t;
if (!slices_.empty())
slices_.back().phaseTimes[activeDagSlot][phase] += t;
phaseTimes[activeDagSlot][phase] += t;
phaseStartTimes[phase] = TimeStamp();
}
@ -1343,8 +1365,8 @@ Statistics::endParallelPhase(Phase phase, const GCParallelTask* task)
{
phaseNestingDepth--;
if (!slices.empty())
slices.back().phaseTimes[PHASE_DAG_NONE][phase] += task->duration();
if (!slices_.empty())
slices_.back().phaseTimes[PHASE_DAG_NONE][phase] += task->duration();
phaseTimes[PHASE_DAG_NONE][phase] += task->duration();
phaseStartTimes[phase] = TimeStamp();
}
@ -1376,26 +1398,28 @@ Statistics::endSCC(unsigned scc, TimeStamp start)
double
Statistics::computeMMU(TimeDuration window) const
{
MOZ_ASSERT(!slices.empty());
MOZ_ASSERT(!slices_.empty());
TimeDuration gc = slices[0].end - slices[0].start;
TimeDuration gc = slices_[0].end - slices_[0].start;
TimeDuration gcMax = gc;
if (gc >= window)
return 0.0;
int startIndex = 0;
for (size_t endIndex = 1; endIndex < slices.length(); endIndex++) {
gc += slices[endIndex].end - slices[endIndex].start;
for (size_t endIndex = 1; endIndex < slices_.length(); endIndex++) {
auto& startSlice = slices_[startIndex];
auto& endSlice = slices_[endIndex];
gc += endSlice.end - endSlice.start;
while (slices[endIndex].end - slices[startIndex].end >= window) {
gc -= slices[startIndex].end - slices[startIndex].start;
while (endSlice.end - startSlice.end >= window) {
gc -= startSlice.end - startSlice.start;
startIndex++;
}
TimeDuration cur = gc;
if (slices[endIndex].end - slices[startIndex].start > window)
cur -= (slices[endIndex].end - slices[startIndex].start - window);
if (endSlice.end - startSlice.start > window)
cur -= (endSlice.end - startSlice.start - window);
if (cur > gcMax)
gcMax = cur;
}
@ -1444,7 +1468,7 @@ Statistics::printProfileTimes(const ProfileDurations& times)
void
Statistics::printSliceProfile()
{
const SliceData& slice = slices.back();
const SliceData& slice = slices_.back();
maybePrintProfileHeaders();

21
js/src/gc/Statistics.h
View File

@ -251,7 +251,7 @@ struct Statistics
void reset(gc::AbortReason reason) {
MOZ_ASSERT(reason != gc::AbortReason::None);
if (!aborted)
slices.back().resetReason = reason;
slices_.back().resetReason = reason;
}
void nonincremental(gc::AbortReason reason) {
@ -283,7 +283,7 @@ struct Statistics
UniqueChars formatCompactSliceMessage() const;
UniqueChars formatCompactSummaryMessage() const;
UniqueChars formatJsonMessage(uint64_t timestamp) const;
UniqueChars formatJsonMessage(uint64_t timestamp, bool includeSlices = true) const;
UniqueChars formatDetailedMessage() const;
JS::GCSliceCallback setSliceCallback(JS::GCSliceCallback callback);
@ -328,10 +328,16 @@ struct Statistics
};
typedef Vector<SliceData, 8, SystemAllocPolicy> SliceDataVector;
typedef SliceDataVector::ConstRange SliceRange;
SliceRange sliceRange() const { return slices.all(); }
size_t slicesLength() const { return slices.length(); }
const SliceDataVector& slices() const { return slices_; }
TimeStamp start() const {
return slices_[0].start;
}
TimeStamp end() const {
return slices_.back().end;
}
// Occasionally print header lines for profiling information.
void maybePrintProfileHeaders();
@ -342,6 +348,9 @@ struct Statistics
// Print total profile times on shutdown.
void printTotalProfileTimes();
// Return JSON for the timings of just the given slice.
UniqueChars formatJsonSlice(size_t sliceNum) const;
private:
JSRuntime* runtime;
@ -354,7 +363,7 @@ struct Statistics
gc::AbortReason nonincrementalReason_;
SliceDataVector slices;
SliceDataVector slices_;
/* Most recent time when the given phase started. */
EnumeratedArray<Phase, PHASE_LIMIT, TimeStamp> phaseStartTimes;

39
js/src/jsgc.cpp
View File

@ -257,6 +257,7 @@ using mozilla::Get;
using mozilla::HashCodeScrambler;
using mozilla::Maybe;
using mozilla::Swap;
using mozilla::TimeStamp;
using JS::AutoGCRooter;
@ -7645,6 +7646,44 @@ JS::GCDescription::formatJSON(JSContext* cx, uint64_t timestamp) const
return out.release();
}
TimeStamp
JS::GCDescription::startTime(JSContext* cx) const
{
return cx->runtime()->gc.stats().start();
}
TimeStamp
JS::GCDescription::endTime(JSContext* cx) const
{
return cx->runtime()->gc.stats().end();
}
TimeStamp
JS::GCDescription::lastSliceStart(JSContext* cx) const
{
return cx->runtime()->gc.stats().slices().back().start;
}
TimeStamp
JS::GCDescription::lastSliceEnd(JSContext* cx) const
{
return cx->runtime()->gc.stats().slices().back().end;
}
JS::UniqueChars
JS::GCDescription::sliceToJSON(JSContext* cx) const
{
size_t slices = cx->runtime()->gc.stats().slices().length();
MOZ_ASSERT(slices > 0);
return cx->runtime()->gc.stats().formatJsonSlice(slices - 1);
}
JS::UniqueChars
JS::GCDescription::summaryToJSON(JSContext* cx) const
{
return cx->runtime()->gc.stats().formatJsonMessage(0, false);
}
JS_PUBLIC_API(JS::GCSliceCallback)
JS::SetGCSliceCallback(JSContext* cx, GCSliceCallback callback)
{

8
js/src/vm/Debugger.cpp
View File

@ -11712,21 +11712,21 @@ GarbageCollectionEvent::Create(JSRuntime* rt, ::js::gcstats::Statistics& stats,
data->nonincrementalReason = stats.nonincrementalReason();
for (auto range = stats.sliceRange(); !range.empty(); range.popFront()) {
for (auto& slice : stats.slices()) {
if (!data->reason) {
// There is only one GC reason for the whole cycle, but for legacy
// reasons this data is stored and replicated on each slice. Each
// slice used to have its own GCReason, but now they are all the
// same.
data->reason = gcreason::ExplainReason(range.front().reason);
data->reason = gcreason::ExplainReason(slice.reason);
MOZ_ASSERT(data->reason);
}
if (!data->collections.growBy(1))
return nullptr;
data->collections.back().startTimestamp = range.front().start;
data->collections.back().endTimestamp = range.front().end;
data->collections.back().startTimestamp = slice.start;
data->collections.back().endTimestamp = slice.end;
}
return data;