Bug 1400153 - Add another check for timestamp problems, and attempt to get all the intermittents routed to one bug, r=jonco
authorSteve Fink <sfink@mozilla.com>
Fri, 20 Apr 2018 11:35:28 -0700
changeset 415111 5bfd3b3d6cc2c45e0682342071d0f635aca86741
parent 415110 7ce50d118d22a3a27be3b5761d05c7bb5d3d8c1a
child 415112 c8375fd1486018c5bfd33f5880cdd7ceab2fdd2a
push id102504
push usersfink@mozilla.com
push dateMon, 23 Apr 2018 23:41:55 +0000
treeherdermozilla-inbound@5bfd3b3d6cc2 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjonco
bugs1400153
milestone61.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
Bug 1400153 - Add another check for timestamp problems, and attempt to get all the intermittents routed to one bug, r=jonco
js/src/gc/Statistics.cpp
js/src/gc/Statistics.h
--- 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;