author | Steve Fink <sfink@mozilla.com> |
Fri, 20 Apr 2018 11:35:28 -0700 | |
changeset 415188 | 5bfd3b3d6cc2c45e0682342071d0f635aca86741 |
parent 415187 | 7ce50d118d22a3a27be3b5761d05c7bb5d3d8c1a |
child 415189 | c8375fd1486018c5bfd33f5880cdd7ceab2fdd2a |
push id | 33892 |
push user | ebalazs@mozilla.com |
push date | Tue, 24 Apr 2018 09:42:58 +0000 |
treeherder | mozilla-central@26e53729a109 [default view] [failures only] |
perfherder | [talos] [build metrics] [platform microbench] (compared to previous push) |
reviewers | jonco |
bugs | 1400153 |
milestone | 61.0a1 |
first release with | nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
|
last release without | nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
|
js/src/gc/Statistics.cpp | file | annotate | diff | comparison | revisions | |
js/src/gc/Statistics.h | file | annotate | diff | comparison | revisions |
--- a/js/src/gc/Statistics.cpp +++ b/js/src/gc/Statistics.cpp @@ -629,17 +629,17 @@ Statistics::formatJsonDescription(uint64 const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50)); json.property("mmu_20ms", int(mmu20 * 100)); // #12 json.property("mmu_50ms", int(mmu50 * 100)); // #13 TimeDuration sccTotal, sccLongest; 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 uint32_t addedChunks = getCount(STAT_NEW_CHUNK); if (addedChunks) json.property("added_chunks", addedChunks); // #18 uint32_t removedChunks = getCount(STAT_DESTROY_CHUNK); if (removedChunks) @@ -865,17 +865,17 @@ LongestPhaseSelfTimeInMajorGC(const Stat // time. for (auto i : AllPhases()) { Phase parent = phases[i].parent; if (parent != Phase::NONE) { bool ok = CheckSelfTime(parent, i, times, selfTimes, times[i]); // 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; selfTimes[parent] -= times[i]; } } // Sum expanded phases corresponding to the same phase. @@ -1094,16 +1094,19 @@ Statistics::endSlice() if (last) { for (auto& count : counts) count = 0; // Clear the timers at the end of a GC, preserving the data for PhaseKind::MUTATOR. 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; } aborted = false; } @@ -1207,18 +1210,17 @@ Statistics::recordPhaseBegin(Phase phase MOZ_ASSERT(phaseStack.length() < MAX_PHASE_NESTING); Phase current = currentPhase(); MOZ_ASSERT(phases[phase].parent == current); 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; } } phaseStack.infallibleAppend(phase); phaseStartTimes[phase] = now; @@ -1228,33 +1230,55 @@ void Statistics::recordPhaseEnd(Phase phase) { MOZ_ASSERT(CurrentThreadCanAccessRuntime(runtime)); MOZ_ASSERT(phaseStartTimes[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; } if (phase == Phase::MUTATOR) timedGCStart = now; phaseStack.popBack(); TimeDuration t = now - phaseStartTimes[phase]; if (!slices_.empty()) slices_.back().phaseTimes[phase] += t; phaseTimes[phase] += t; phaseStartTimes[phase] = TimeStamp(); + +#ifdef DEBUG + phaseEndTimes[phase] = now; +#endif } void Statistics::endPhase(PhaseKind phaseKind) { Phase phase = currentPhase(); MOZ_ASSERT(phase != Phase::NONE); MOZ_ASSERT(phases[phase].phaseKind == phaseKind);
--- a/js/src/gc/Statistics.h +++ b/js/src/gc/Statistics.h @@ -284,16 +284,21 @@ struct Statistics gc::AbortReason nonincrementalReason_; SliceDataVector slices_; /* 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; /* Total time in a given phase for this GC. */ PhaseTimeTable phaseTimes; PhaseTimeTable parallelTimes;