Bug 1400153 - Add another check for timestamp problems, and attempt to get all the intermittents routed to one bug, r=jonco

--HG--
extra : rebase_source : 1731917b91ce47a3b6302fbb140ffbdd78b0dba2
extra : amend_source : 79bf89753f9cb8fca9ba66efc858dfd838288a6e
extra : histedit_source : 1d796c678b8967615e434d3fb74c976d8f33f2ca
This commit is contained in:
Steve Fink 2018-04-20 11:35:28 -07:00
parent 29b27943c5
commit d4194e4003
2 changed files with 35 additions and 6 deletions

View File

@ -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

View File

@ -289,6 +289,11 @@ struct Statistics
/* Most recent time when the given phase started. */
EnumeratedArray<Phase, Phase::LIMIT, TimeStamp> phaseStartTimes;
#ifdef DEBUG
/* Most recent time when the given phase ended. */
EnumeratedArray<Phase, Phase::LIMIT, TimeStamp> phaseEndTimes;
#endif
/* Bookkeeping for GC timings when timingMutator is true */
TimeStamp timedGCStart;
TimeDuration timedGCTime;