Bug 1735434 - Gather additional information for cycle collection profiler markers r=mccr8

Differential Revision: https://phabricator.services.mozilla.com/D128316
This commit is contained in:
Steve Fink 2022-04-29 20:07:23 +00:00
Родитель 83a758a1fb
Коммит 036abc801c
7 изменённых файлов: 126 добавлений и 67 удалений

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

@ -107,6 +107,82 @@
* various kinds.
*/
#ifdef MOZ_GECKO_PROFILER
namespace geckoprofiler::markers {
struct CCIntervalMarker {
static constexpr mozilla::Span<const char> MarkerTypeName() {
return mozilla::MakeStringSpan("CC");
}
static void StreamJSONMarkerData(
mozilla::baseprofiler::SpliceableJSONWriter& aWriter, bool aIsStart,
const mozilla::ProfilerString8View& aReason,
uint32_t aForgetSkippableBeforeCC, uint32_t aSuspectedAtCCStart,
uint32_t aRemovedPurples, const mozilla::CycleCollectorResults& aResults,
mozilla::TimeDuration aMaxSliceTime) {
if (aIsStart) {
aWriter.StringProperty("mReason", aReason);
aWriter.IntProperty("mSuspected", aSuspectedAtCCStart);
aWriter.IntProperty("mForgetSkippable", aForgetSkippableBeforeCC);
aWriter.IntProperty("mRemovedPurples", aRemovedPurples);
} else {
aWriter.TimeDoubleMsProperty("mMaxSliceTime",
aMaxSliceTime.ToMilliseconds());
aWriter.IntProperty("mSlices", aResults.mNumSlices);
aWriter.BoolProperty("mAnyManual", aResults.mAnyManual);
aWriter.BoolProperty("mForcedGC", aResults.mForcedGC);
aWriter.BoolProperty("mMergedZones", aResults.mMergedZones);
aWriter.IntProperty("mVisitedRefCounted", aResults.mVisitedRefCounted);
aWriter.IntProperty("mVisitedGCed", aResults.mVisitedGCed);
aWriter.IntProperty("mFreedRefCounted", aResults.mFreedRefCounted);
aWriter.IntProperty("mFreedGCed", aResults.mFreedGCed);
aWriter.IntProperty("mFreedJSZones", aResults.mFreedJSZones);
}
}
static mozilla::MarkerSchema MarkerTypeDisplay() {
using MS = mozilla::MarkerSchema;
MS schema{MS::Location::MarkerChart, MS::Location::MarkerTable,
MS::Location::TimelineMemory};
schema.AddStaticLabelValue(
"Description",
"Summary data for the core part of a cycle collection, possibly "
"encompassing a set of incremental slices. The main thread is not "
"blocked for the entire major CC interval, only for the individual "
"slices.");
schema.AddKeyLabelFormatSearchable("mReason", "Reason", MS::Format::String,
MS::Searchable::Searchable);
schema.AddKeyLabelFormat("mMaxSliceTime", "Max Slice Time",
MS::Format::Duration);
schema.AddKeyLabelFormat("mSuspected", "Suspected Objects",
MS::Format::Integer);
schema.AddKeyLabelFormat("mSlices", "Number of Slices",
MS::Format::Integer);
schema.AddKeyLabelFormat("mAnyManual", "Manually Triggered",
MS::Format::Integer);
schema.AddKeyLabelFormat("mForcedGC", "GC Forced", MS::Format::Integer);
schema.AddKeyLabelFormat("mMergedZones", "Zones Merged",
MS::Format::Integer);
schema.AddKeyLabelFormat("mForgetSkippable", "Forget Skippables",
MS::Format::Integer);
schema.AddKeyLabelFormat("mVisitedRefCounted", "Refcounted Objects Visited",
MS::Format::Integer);
schema.AddKeyLabelFormat("mVisitedGCed", "GC Objects Visited",
MS::Format::Integer);
schema.AddKeyLabelFormat("mFreedRefCounted", "Refcounted Objects Freed",
MS::Format::Integer);
schema.AddKeyLabelFormat("mFreedGCed", "GC Objects Freed",
MS::Format::Integer);
schema.AddKeyLabelFormat("mCollectedGCZones", "JS Zones Freed",
MS::Format::Integer);
schema.AddKeyLabelFormat("mRemovedPurples",
"Objects Removed From Purple Buffer",
MS::Format::Integer);
return schema;
}
};
} // namespace geckoprofiler::markers
#endif
namespace mozilla {
void CCGCScheduler::NoteGCBegin() {
@ -147,52 +223,30 @@ void CCGCScheduler::NoteGCEnd() {
}
}
#ifdef MOZ_GECKO_PROFILER
struct CCIntervalMarker {
static constexpr mozilla::Span<const char> MarkerTypeName() {
return mozilla::MakeStringSpan("CC");
}
static void StreamJSONMarkerData(
baseprofiler::SpliceableJSONWriter& aWriter,
const mozilla::ProfilerString8View& aReason) {
if (aReason.Length()) {
aWriter.StringProperty("reason", aReason);
}
}
static mozilla::MarkerSchema MarkerTypeDisplay() {
using MS = mozilla::MarkerSchema;
MS schema{MS::Location::MarkerChart, MS::Location::MarkerTable,
MS::Location::TimelineMemory};
schema.AddStaticLabelValue(
"Description",
"Summary data for the core part of a cycle collection, possibly "
"encompassing a set of incremental slices. The main thread is not "
"blocked for the entire major CC interval, only for the individual "
"slices.");
schema.AddKeyLabelFormatSearchable("reason", "Reason", MS::Format::String,
MS::Searchable::Searchable);
return schema;
}
};
#endif
void CCGCScheduler::NoteCCBegin(CCReason aReason, TimeStamp aWhen) {
#ifdef MOZ_GECKO_PROFILER
profiler_add_marker(
"CC", baseprofiler::category::GCCC,
MarkerOptions(MarkerTiming::IntervalStart(aWhen)), CCIntervalMarker{},
ProfilerString8View::WrapNullTerminatedString(CCReasonToString(aReason)));
#endif
void CCGCScheduler::NoteCCBegin(CCReason aReason, TimeStamp aWhen,
uint32_t aNumForgetSkippables,
uint32_t aSuspected, uint32_t aRemovedPurples) {
CycleCollectorResults ignoredResults;
PROFILER_MARKER(
"CC", GCCC, MarkerOptions(MarkerTiming::IntervalStart(aWhen)),
CCIntervalMarker,
/* aIsStart */ true,
ProfilerString8View::WrapNullTerminatedString(CCReasonToString(aReason)),
aNumForgetSkippables, aSuspected, aRemovedPurples, ignoredResults,
TimeDuration());
mIsCollectingCycles = true;
}
void CCGCScheduler::NoteCCEnd(TimeStamp aWhen) {
#ifdef MOZ_GECKO_PROFILER
profiler_add_marker("CC", baseprofiler::category::GCCC,
MarkerOptions(MarkerTiming::IntervalEnd(aWhen)),
CCIntervalMarker{}, nullptr);
#endif
void CCGCScheduler::NoteCCEnd(const CycleCollectorResults& aResults,
TimeStamp aWhen,
mozilla::TimeDuration aMaxSliceTime) {
mCCollectedWaitingForGC += aResults.mFreedGCed;
mCCollectedZonesWaitingForGC += aResults.mFreedJSZones;
PROFILER_MARKER("CC", GCCC, MarkerOptions(MarkerTiming::IntervalEnd(aWhen)),
CCIntervalMarker, /* aIsStart */ false, nullptr, 0, 0, 0,
aResults, aMaxSliceTime);
mIsCollectingCycles = false;
mLastCCEndTime = aWhen;
@ -604,8 +658,8 @@ js::SliceBudget CCGCScheduler::ComputeCCSliceBudget(
TimeDuration baseBudget =
aDeadline.IsNull() ? kICCSliceBudget : aDeadline - aNow;
if (aCCBeginTime.IsNull()) {
// If no CC is in progress, use the standard slice time.
if (aPrevSliceEndTime.IsNull()) {
// The first slice gets the standard slice time.
return js::SliceBudget(js::TimeBudget(baseBudget));
}

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

@ -245,13 +245,16 @@ class CCGCScheduler {
// This is invoked when we reach the actual cycle collection portion of the
// overall cycle collection.
void NoteCCBegin(CCReason aReason, TimeStamp aWhen);
void NoteCCBegin(CCReason aReason, TimeStamp aWhen,
uint32_t aNumForgetSkippables, uint32_t aSuspected,
uint32_t aRemovedPurples);
// This is invoked when the whole process of collection is done -- i.e., CC
// preparation (eg ForgetSkippables) in addition to the CC itself. There
// really ought to be a separate name for the overall CC as opposed to the
// actual cycle collection portion.
void NoteCCEnd(TimeStamp aWhen);
void NoteCCEnd(const CycleCollectorResults& aResults, TimeStamp aWhen,
mozilla::TimeDuration aMaxSliceTime);
void NoteGCSliceEnd(TimeDuration aSliceDuration) {
if (mMajorGCReason == JS::GCReason::NO_REASON) {
@ -304,13 +307,6 @@ class CCGCScheduler {
return aSuspectedBeforeForgetSkippable - aSuspectedCCObjects;
}
// After collecting cycles, record the results that are used in scheduling
// decisions.
void NoteCycleCollected(const CycleCollectorResults& aResults) {
mCCollectedWaitingForGC += aResults.mFreedGCed;
mCCollectedZonesWaitingForGC += aResults.mFreedJSZones;
}
// Test if we are in the NoteCCBegin .. NoteCCEnd interval.
bool IsCollectingCycles() const { return mIsCollectingCycles; }

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

@ -106,6 +106,7 @@ struct CycleCollectorStats {
constexpr CycleCollectorStats() = default;
void Init();
void Clear();
void PrepareForCycleCollection(TimeStamp aNow);
void AfterPrepareForCycleCollectionSlice(TimeStamp aDeadline,
TimeStamp aBeginTime,
TimeStamp aMaybeAfterGCTime);
@ -1242,6 +1243,11 @@ void CycleCollectorStats::AfterCycleCollectionSlice() {
mBeginSliceTime = TimeStamp();
}
void CycleCollectorStats::PrepareForCycleCollection(TimeStamp aNow) {
mBeginTime = aNow;
mSuspected = nsCycleCollector_suspectedCount();
}
void CycleCollectorStats::AfterPrepareForCycleCollectionSlice(
TimeStamp aDeadline, TimeStamp aBeginTime, TimeStamp aMaybeAfterGCTime) {
mBeginSliceTime = aBeginTime;
@ -1427,7 +1433,10 @@ void nsJSContext::PrepareForCycleCollectionSlice(CCReason aReason,
}
if (!sScheduler.IsCollectingCycles()) {
sScheduler.NoteCCBegin(aReason, beginTime);
sCCStats.PrepareForCycleCollection(beginTime);
sScheduler.NoteCCBegin(aReason, beginTime,
sCCStats.mForgetSkippableBeforeCC,
sCCStats.mSuspected, sCCStats.mRemovedPurples);
}
sCCStats.AfterPrepareForCycleCollectionSlice(aDeadline, beginTime,
@ -1487,9 +1496,7 @@ void nsJSContext::BeginCycleCollectionCallback(CCReason aReason) {
MOZ_ASSERT(NS_IsMainThread());
TimeStamp startTime = TimeStamp::Now();
sCCStats.mBeginTime =
sCCStats.mBeginSliceTime.IsNull() ? startTime : sCCStats.mBeginSliceTime;
sCCStats.mSuspected = nsCycleCollector_suspectedCount();
sCCStats.PrepareForCycleCollection(startTime);
// Run forgetSkippable synchronously to reduce the size of the CC graph. This
// is particularly useful if we recently finished a GC.
@ -1510,7 +1517,8 @@ void nsJSContext::BeginCycleCollectionCallback(CCReason aReason) {
}
// static
void nsJSContext::EndCycleCollectionCallback(CycleCollectorResults& aResults) {
void nsJSContext::EndCycleCollectionCallback(
const CycleCollectorResults& aResults) {
MOZ_ASSERT(NS_IsMainThread());
sScheduler.KillCCRunner();
@ -1519,7 +1527,6 @@ void nsJSContext::EndCycleCollectionCallback(CycleCollectorResults& aResults) {
// we previously called PrepareForCycleCollectionSlice(). During shutdown
// CCs, this won't happen.
sCCStats.AfterCycleCollectionSlice();
sScheduler.NoteCycleCollected(aResults);
TimeStamp endCCTimeStamp = TimeStamp::Now();
TimeDuration ccNowDuration = TimeBetween(sCCStats.mBeginTime, endCCTimeStamp);
@ -1539,6 +1546,7 @@ void nsJSContext::EndCycleCollectionCallback(CycleCollectorResults& aResults) {
// Log information about the CC via telemetry, JSON and the console.
sCCStats.SendTelemetry(ccNowDuration);
sScheduler.NoteCCEnd(aResults, endCCTimeStamp, sCCStats.mMaxSliceTime);
uint32_t cleanups = std::max(sCCStats.mForgetSkippableBeforeCC, 1u);
@ -1547,7 +1555,6 @@ void nsJSContext::EndCycleCollectionCallback(CycleCollectorResults& aResults) {
sCCStats.MaybeNotifyStats(aResults, ccNowDuration, cleanups);
// Update global state to indicate we have just run a cycle collection.
sScheduler.NoteCCEnd(endCCTimeStamp);
sCCStats.Clear();
}
@ -1745,8 +1752,7 @@ static void DOMGCSliceCallback(JSContext* aCx, JS::GCProgress aProgress,
// May need to kill the GC runner
sScheduler.KillGCRunner();
TimeStamp now = TimeStamp::Now();
sScheduler.MaybePokeCC(now, nsCycleCollector_suspectedCount());
nsJSContext::MaybePokeCC();
if (aDesc.isZone_) {
sScheduler.PokeFullGC();
@ -1755,7 +1761,8 @@ static void DOMGCSliceCallback(JSContext* aCx, JS::GCProgress aProgress,
sScheduler.KillFullGCTimer();
}
if (sScheduler.IsCCNeeded(now, nsCycleCollector_suspectedCount()) !=
if (sScheduler.IsCCNeeded(TimeStamp::Now(),
nsCycleCollector_suspectedCount()) !=
CCReason::NO_REASON) {
nsCycleCollector_dispatchDeferredDeletion();
}

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

@ -86,7 +86,7 @@ class nsJSContext : public nsIScriptContext {
static void BeginCycleCollectionCallback(mozilla::CCReason aReason);
static void EndCycleCollectionCallback(
mozilla::CycleCollectorResults& aResults);
const mozilla::CycleCollectorResults& aResults);
// Return the longest CC slice time since ClearMaxCCSliceTime() was last
// called.

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

@ -147,6 +147,7 @@ void TestCC::TimerFires(int aNumSlices) {
step = mScheduler.AdvanceCCRunner(idleDeadline, Now(), SuspectedCCObjects());
EXPECT_EQ(step.mAction, CCRunnerAction::CleanupDeferred);
mScheduler.NoteCCBegin(CCReason::API, Now(), 0, sSuspected, 0);
RunSlices(aNumSlices);
}
@ -177,8 +178,7 @@ void TestCC::EndCycleCollectionCallback() {
CycleCollectorResults results;
results.mFreedGCed = 10;
results.mFreedJSZones = 2;
mScheduler.NoteCycleCollected(results);
mScheduler.NoteCCEnd(Now());
mScheduler.NoteCCEnd(results, Now(), TimeDuration());
// Because > 0 zones were freed.
EXPECT_TRUE(mScheduler.NeedsGCAfterCC());
@ -186,7 +186,6 @@ void TestCC::EndCycleCollectionCallback() {
void TestCC::KillCCRunner() {
// nsJSContext::KillCCRunner
mScheduler.NoteCCEnd(Now());
mScheduler.KillCCRunner();
}

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

@ -46,6 +46,7 @@ struct CycleCollectorResults {
void Init() {
mForcedGC = false;
mSuspectedAtCCStart = 0;
mMergedZones = false;
mAnyManual = false;
mVisitedRefCounted = 0;
@ -62,6 +63,7 @@ struct CycleCollectorResults {
bool mMergedZones;
// mAnyManual is true if any slice was manually triggered, and at shutdown.
bool mAnyManual;
uint32_t mSuspectedAtCCStart;
uint32_t mVisitedRefCounted;
uint32_t mVisitedGCed;
uint32_t mFreedRefCounted;

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

@ -3599,6 +3599,7 @@ void nsCycleCollector::BeginCollection(
JS::AutoEnterCycleCollection autocc(mCCJSRuntime->Runtime());
mGraph.Init();
mResults.Init();
mResults.mSuspectedAtCCStart = SuspectedCount();
mResults.mAnyManual = aIsManual;
bool mergeZones = ShouldMergeZones(aIsManual);
mResults.mMergedZones = mergeZones;