diff --git a/js/src/gc/Statistics.cpp b/js/src/gc/Statistics.cpp index 04e08143a538..304ed92af9fb 100644 --- a/js/src/gc/Statistics.cpp +++ b/js/src/gc/Statistics.cpp @@ -634,7 +634,7 @@ Statistics::formatJsonDescription(uint64_t timestamp, JSONPrinter& json) const sccDurations(&sccTotal, &sccLongest); json.property("scc_sweep_total", sccTotal, JSONPrinter::MILLISECONDS); // #14 json.property("scc_sweep_max_pause", sccLongest, JSONPrinter::MILLISECONDS); // #15 - + if (nonincrementalReason_ != AbortReason::None) json.property("nonincremental_reason", ExplainAbortReason(nonincrementalReason_)); // #16 json.property("allocated_bytes", preBytes); // #17 @@ -870,7 +870,7 @@ LongestPhaseSelfTimeInMajorGC(const Statistics::PhaseTimeTable& times) // This happens very occasionally in release builds. Skip collecting // longest phase telemetry if it does. - MOZ_ASSERT(ok, "Inconsistent time data"); + MOZ_ASSERT(ok, "Inconsistent time data; see bug 1400153"); if (!ok) return PhaseKind::NONE; @@ -1099,6 +1099,9 @@ Statistics::endSlice() auto mutatorStartTime = phaseStartTimes[Phase::MUTATOR]; auto mutatorTime = phaseTimes[Phase::MUTATOR]; PodZero(&phaseStartTimes); +#ifdef DEBUG + PodZero(&phaseEndTimes); +#endif PodZero(&phaseTimes); phaseStartTimes[Phase::MUTATOR] = mutatorStartTime; phaseTimes[Phase::MUTATOR] = mutatorTime; @@ -1212,8 +1215,7 @@ Statistics::recordPhaseBegin(Phase phase) TimeStamp now = TimeStamp::Now(); if (current != Phase::NONE) { - // Sadly this happens sometimes. - MOZ_ASSERT(now >= phaseStartTimes[currentPhase()]); + MOZ_ASSERT(now >= phaseStartTimes[currentPhase()], "Inconsistent time data; see bug 1400153"); if (now < phaseStartTimes[currentPhase()]) { now = phaseStartTimes[currentPhase()]; aborted = true; @@ -1233,8 +1235,26 @@ Statistics::recordPhaseEnd(Phase phase) TimeStamp now = TimeStamp::Now(); - // Sadly this happens sometimes. - MOZ_ASSERT(now >= phaseStartTimes[phase]); + // Make sure this phase ends after it starts. + MOZ_ASSERT(now >= phaseStartTimes[phase], "Inconsistent time data; see bug 1400153"); + +#ifdef DEBUG + // Make sure this phase ends after all of its children. Note that some + // children might not have run in this instance, in which case they will + // have run in a previous instance of this parent or not at all. + for (Phase kid = phases[phase].firstChild; kid != Phase::NONE; kid = phases[kid].nextSibling) { + if (phaseEndTimes[kid].IsNull()) + continue; + if (phaseEndTimes[kid] > now) + fprintf(stderr, "Parent %s ended at %.3fms, before child %s ended at %.3fms?\n", + phases[phase].name, + t(now - TimeStamp::ProcessCreation()), + phases[kid].name, + t(phaseEndTimes[kid] - TimeStamp::ProcessCreation())); + MOZ_ASSERT(phaseEndTimes[kid] <= now, "Inconsistent time data; see bug 1400153"); + } +#endif + if (now < phaseStartTimes[phase]) { now = phaseStartTimes[phase]; aborted = true; @@ -1250,6 +1270,10 @@ Statistics::recordPhaseEnd(Phase phase) slices_.back().phaseTimes[phase] += t; phaseTimes[phase] += t; phaseStartTimes[phase] = TimeStamp(); + +#ifdef DEBUG + phaseEndTimes[phase] = now; +#endif } void diff --git a/js/src/gc/Statistics.h b/js/src/gc/Statistics.h index ddedd1618df0..7775e3e71e39 100644 --- a/js/src/gc/Statistics.h +++ b/js/src/gc/Statistics.h @@ -289,6 +289,11 @@ struct Statistics /* Most recent time when the given phase started. */ EnumeratedArray phaseStartTimes; +#ifdef DEBUG + /* Most recent time when the given phase ended. */ + EnumeratedArray phaseEndTimes; +#endif + /* Bookkeeping for GC timings when timingMutator is true */ TimeStamp timedGCStart; TimeDuration timedGCTime;