Bug 1366217 - Discard GC stats if timing inconsistencies are found. r=sfink, a=lizzard
authorJon Coppeard <jcoppeard@mozilla.com>
Fri, 04 Aug 2017 10:11:12 +0100
changeset 423934 83a250a0a345c83cac9a46c27f7a8c9dd77e264a
parent 423933 d0fb17cf639bff43bde763ae81515bca8089047d
child 423935 c141e8fe733b1841f9fb1233eda37e01d9e88cb7
push id1517
push userjlorenzo@mozilla.com
push dateThu, 14 Sep 2017 16:50:54 +0000
treeherdermozilla-release@3b41fd564418 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerssfink, lizzard
bugs1366217
milestone56.0
Bug 1366217 - Discard GC stats if timing inconsistencies are found. r=sfink, a=lizzard
js/src/gc/Statistics.cpp
js/src/vm/HelperThreads.cpp
--- a/js/src/gc/Statistics.cpp
+++ b/js/src/gc/Statistics.cpp
@@ -784,49 +784,58 @@ SumPhase(PhaseKind phaseKind, const Stat
          phase != Phase::NONE;
          phase = phases[phase].nextInPhase)
     {
         sum += times[phase];
     }
     return sum;
 }
 
-static void
+static bool
 CheckSelfTime(Phase parent,
               Phase child,
               const Statistics::PhaseTimeTable& times,
               const Statistics::PhaseTimeTable& selfTimes,
               TimeDuration childTime)
 {
     if (selfTimes[parent] < childTime) {
         fprintf(stderr,
                 "Parent %s time = %.3fms with %.3fms remaining, child %s time %.3fms\n",
                 phases[parent].name,
                 times[parent].ToMilliseconds(),
                 selfTimes[parent].ToMilliseconds(),
                 phases[child].name,
                 childTime.ToMilliseconds());
         fflush(stderr);
-        MOZ_CRASH();
+        return false;
     }
+
+    return true;
 }
 
 static PhaseKind
 LongestPhaseSelfTimeInMajorGC(const Statistics::PhaseTimeTable& times)
 {
     // Start with total times per expanded phase, including children's times.
     Statistics::PhaseTimeTable selfTimes(times);
 
     // We have the total time spent in each phase, including descendant times.
     // Loop over the children and subtract their times from their parent's self
     // time.
     for (auto i : AllPhases()) {
         Phase parent = phases[i].parent;
         if (parent != Phase::NONE) {
-            CheckSelfTime(parent, i, times, selfTimes, times[i]);
+            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");
+            if (!ok)
+                return PhaseKind::NONE;
+
             selfTimes[parent] -= times[i];
         }
     }
 
     // Sum expanded phases corresponding to the same phase.
     EnumeratedArray<PhaseKind, PhaseKind::LIMIT, TimeDuration> phaseTimes;
     for (auto i : AllPhaseKinds())
         phaseTimes[i] = SumPhase(i, selfTimes);
@@ -1155,49 +1164,43 @@ 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) {
-#ifdef ANDROID
         // Sadly this happens sometimes.
+        MOZ_ASSERT(now >= phaseStartTimes[currentPhase()]);
         if (now < phaseStartTimes[currentPhase()]) {
             now = phaseStartTimes[currentPhase()];
             aborted = true;
         }
-#endif
-
-        MOZ_RELEASE_ASSERT(now >= phaseStartTimes[currentPhase()]);
     }
 
     phaseStack.infallibleAppend(phase);
     phaseStartTimes[phase] = now;
 }
 
 void
 Statistics::recordPhaseEnd(Phase phase)
 {
     MOZ_ASSERT(CurrentThreadCanAccessRuntime(runtime));
 
     MOZ_ASSERT(phaseStartTimes[phase]);
 
     TimeStamp now = TimeStamp::Now();
 
-#ifdef ANDROID
     // Sadly this happens sometimes.
+    MOZ_ASSERT(now >= phaseStartTimes[phase]);
     if (now < phaseStartTimes[phase]) {
         now = phaseStartTimes[phase];
         aborted = true;
     }
-#endif
-
-    MOZ_RELEASE_ASSERT(now >= phaseStartTimes[phase]);
 
     if (phase == Phase::MUTATOR)
         timedGCStart = now;
 
     phaseStack.popBack();
 
     TimeDuration t = now - phaseStartTimes[phase];
     if (!slices_.empty())
--- a/js/src/vm/HelperThreads.cpp
+++ b/js/src/vm/HelperThreads.cpp
@@ -1322,22 +1322,20 @@ js::GCParallelTask::join()
     joinWithLockHeld(helperLock);
 }
 
 static inline
 TimeDuration
 TimeSince(TimeStamp prev)
 {
     TimeStamp now = TimeStamp::Now();
-#ifdef ANDROID
     // Sadly this happens sometimes.
+    MOZ_ASSERT(now >= prev);
     if (now < prev)
         now = prev;
-#endif
-    MOZ_RELEASE_ASSERT(now >= prev);
     return now - prev;
 }
 
 void
 js::GCParallelTask::runFromActiveCooperatingThread(JSRuntime* rt)
 {
     MOZ_ASSERT(state == NotStarted);
     MOZ_ASSERT(js::CurrentThreadCanAccessRuntime(rt));