Backed out changesets 472a1be79a9f, 2b43b310858b, and adc20d941bd8 (bug 948554) for Win7 debug xpcshell timeouts.
authorRyan VanderMeulen <ryanvm@gmail.com>
Wed, 18 Dec 2013 19:03:28 -0500
changeset 177195 b464f609a19354de4dfa67a0d42b0b4b6fd69d7b
parent 177194 a2d86e1bf7743e166a70d3880eaf23abbe0889ee
child 177196 a3287212603e08e3f60de7552b5e822a977caea5
push id3343
push userffxbld
push dateMon, 17 Mar 2014 21:55:32 +0000
treeherdermozilla-beta@2f7d3415f79f [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
bugs948554
milestone29.0a1
backs out472a1be79a9f38225cd8a6741594957c0a53d669
2b43b310858be199ffd84ce66d90372fa2c0cc9d
adc20d941bd8284ec6f5c4300cf42308c93042d8
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
Backed out changesets 472a1be79a9f, 2b43b310858b, and adc20d941bd8 (bug 948554) for Win7 debug xpcshell timeouts.
dom/base/nsJSEnvironment.cpp
toolkit/components/telemetry/Histograms.json
--- a/dom/base/nsJSEnvironment.cpp
+++ b/dom/base/nsJSEnvironment.cpp
@@ -152,17 +152,17 @@ static const uint32_t kMaxICCDuration = 
 
 static nsITimer *sGCTimer;
 static nsITimer *sShrinkGCBuffersTimer;
 static nsITimer *sCCTimer;
 static nsITimer *sICCTimer;
 static nsITimer *sFullGCTimer;
 static nsITimer *sInterSliceGCTimer;
 
-static TimeStamp sLastCCEndTime;
+static PRTime sLastCCEndTime;
 
 static bool sCCLockedOut;
 static PRTime sCCLockedOutTime;
 
 static JS::GCSliceCallback sPrevGCSliceCallback;
 
 static bool sHasRunGC;
 
@@ -1976,113 +1976,92 @@ FireForgetSkippable(uint32_t aSuspected,
   }
   sTotalForgetSkippableTime += delta;
   sRemovedPurples += (aSuspected - sPreviousSuspectedCount);
   ++sForgetSkippableBeforeCC;
 }
 
 MOZ_ALWAYS_INLINE
 static uint32_t
-TimeBetween(TimeStamp start, TimeStamp end)
+TimeBetween(PRTime start, PRTime end)
 {
   MOZ_ASSERT(end >= start);
-  return (uint32_t) ((end - start).ToMilliseconds());
-}
-
-static uint32_t
-TimeUntilNow(TimeStamp start)
-{
-  return TimeBetween(start, TimeStamp::Now());
+  return (uint32_t)(end - start) / PR_USEC_PER_MSEC;
 }
 
 struct CycleCollectorStats
 {
   void Clear()
   {
-    mBeginSliceTime = TimeStamp();
-    mBeginTime = TimeStamp();
+    mBeginSliceTime = 0;
+    mBeginTime = 0;
     mMaxGCDuration = 0;
     mRanSyncForgetSkippable = false;
     mSuspected = 0;
     mMaxSkippableDuration = 0;
-    mMaxSliceTime = 0;
     mAnyLockedOut = false;
   }
 
-  void PrepareForCycleCollectionSlice(int32_t aExtraForgetSkippableCalls = 0);
-
-  void FinishCycleCollectionSlice()
-  {
-    if (mBeginSliceTime.IsNull()) {
-      return;
-    }
-    uint32_t sliceTime = TimeUntilNow(mBeginSliceTime);
-    mMaxSliceTime = std::max(mMaxSliceTime, sliceTime);
-  }
-
   // Time the current slice began, including any GC finishing.
-  TimeStamp mBeginSliceTime;
+  PRTime mBeginSliceTime;
 
   // Time the current cycle collection began.
-  TimeStamp mBeginTime;
+  PRTime mBeginTime;
 
   // The longest GC finishing duration for any slice of the current CC.
   uint32_t mMaxGCDuration;
 
   // True if we ran sync forget skippable in any slice of the current CC.
   bool mRanSyncForgetSkippable;
 
   // Number of suspected objects at the start of the current CC.
   uint32_t mSuspected;
 
   // The longest duration spent on sync forget skippable in any slice of the
-  // current CC.
+  // current CC
   uint32_t mMaxSkippableDuration;
 
-  // The longest pause of any slice in the current CC.
-  uint32_t mMaxSliceTime;
-
   // True if we were locked out by the GC in any slice of the current CC.
   bool mAnyLockedOut;
 };
 
 CycleCollectorStats gCCStats;
 
 static int64_t
 ICCSliceTime()
 {
   // If CC is not incremental, use an unlimited budget.
   if (!sIncrementalCC) {
     return -1;
   }
 
   // If an ICC is in progress and is taking too long, finish it off.
-  if (!gCCStats.mBeginTime.IsNull() &&
-      TimeUntilNow(gCCStats.mBeginTime) >= kMaxICCDuration) {
+  if (gCCStats.mBeginTime != 0 &&
+      TimeBetween(gCCStats.mBeginTime, PR_Now()) >= kMaxICCDuration) {
     return -1;
   }
 
   return kICCSliceBudget;
 }
 
-void
-CycleCollectorStats::PrepareForCycleCollectionSlice(int32_t aExtraForgetSkippableCalls)
+static void
+PrepareForCycleCollection(int32_t aExtraForgetSkippableCalls = 0)
 {
-  mBeginSliceTime = TimeStamp::Now();
+  gCCStats.mBeginSliceTime = PR_Now();
 
   // Before we begin the cycle collection, make sure there is no active GC.
-  TimeStamp endGCTime;
+  PRTime endGCTime;
   if (sCCLockedOut) {
-    mAnyLockedOut = true;
+    gCCStats.mAnyLockedOut = true;
     FinishAnyIncrementalGC();
-    endGCTime = TimeStamp::Now();
-    uint32_t gcTime = TimeBetween(mBeginSliceTime, endGCTime);
-    mMaxGCDuration = std::max(mMaxGCDuration, gcTime);
+    endGCTime = PR_Now();
+    uint32_t gcTime = TimeBetween(gCCStats.mBeginSliceTime, endGCTime);
+    gCCStats.mMaxGCDuration = std::max(gCCStats.mMaxGCDuration, gcTime);
   } else {
-    endGCTime = mBeginSliceTime;
+    endGCTime = gCCStats.mBeginSliceTime;
   }
 
   // Run forgetSkippable synchronously to reduce the size of the CC graph. This
   // is particularly useful if we recently finished a GC.
   if (aExtraForgetSkippableCalls >= 0) {
     bool ranSyncForgetSkippable = false;
     while (sCleanupsSinceLastGC < NS_MAJOR_FORGET_SKIPPABLE_CALLS) {
       FireForgetSkippable(nsCycleCollector_suspectedCount(), false);
@@ -2090,54 +2069,52 @@ CycleCollectorStats::PrepareForCycleColl
     }
 
     for (int32_t i = 0; i < aExtraForgetSkippableCalls; ++i) {
       FireForgetSkippable(nsCycleCollector_suspectedCount(), false);
       ranSyncForgetSkippable = true;
     }
 
     if (ranSyncForgetSkippable) {
-      mMaxSkippableDuration =
-        std::max(mMaxSkippableDuration, TimeUntilNow(endGCTime));
-      mRanSyncForgetSkippable = true;
+      gCCStats.mMaxSkippableDuration =
+        std::max(gCCStats.mMaxSkippableDuration, TimeBetween(endGCTime, PR_Now()));
+      gCCStats.mRanSyncForgetSkippable = true;
     }
 
   }
 }
 
 //static
 void
 nsJSContext::CycleCollectNow(nsICycleCollectorListener *aListener,
                              int32_t aExtraForgetSkippableCalls)
 {
   if (!NS_IsMainThread()) {
     return;
   }
 
   PROFILER_LABEL("CC", "CycleCollectNow");
-  gCCStats.PrepareForCycleCollectionSlice(aExtraForgetSkippableCalls);
+  PrepareForCycleCollection(aExtraForgetSkippableCalls);
   nsCycleCollector_collect(aListener);
-  gCCStats.FinishCycleCollectionSlice();
 }
 
 //static
 void
 nsJSContext::ScheduledCycleCollectNow(int64_t aSliceTime)
 {
   if (!NS_IsMainThread()) {
     return;
   }
 
   PROFILER_LABEL("CC", "ScheduledCycleCollectNow");
 
   // Ideally, the slice time would be decreased by the amount of
   // time spent on PrepareForCycleCollection().
-  gCCStats.PrepareForCycleCollectionSlice();
+  PrepareForCycleCollection();
   nsCycleCollector_scheduledCollect(aSliceTime);
-  gCCStats.FinishCycleCollectionSlice();
 }
 
 static void
 ICCTimerFired(nsITimer* aTimer, void* aClosure)
 {
   if (sDidShutdown) {
     return;
   }
@@ -2160,17 +2137,17 @@ ICCTimerFired(nsITimer* aTimer, void* aC
 }
 
 //static
 void
 nsJSContext::BeginCycleCollectionCallback()
 {
   MOZ_ASSERT(NS_IsMainThread());
 
-  gCCStats.mBeginTime = gCCStats.mBeginSliceTime.IsNull() ? TimeStamp::Now() : gCCStats.mBeginSliceTime;
+  gCCStats.mBeginTime = gCCStats.mBeginSliceTime ? gCCStats.mBeginSliceTime : PR_Now();
   gCCStats.mSuspected = nsCycleCollector_suspectedCount();
 
   KillCCTimer();
 
   MOZ_ASSERT(!sICCTimer, "Tried to create a new ICC timer when one already existed.");
 
   if (!sIncrementalCC) {
     return;
@@ -2188,39 +2165,35 @@ nsJSContext::BeginCycleCollectionCallbac
 //static
 void
 nsJSContext::EndCycleCollectionCallback(CycleCollectorResults &aResults)
 {
   MOZ_ASSERT(NS_IsMainThread());
 
   nsJSContext::KillICCTimer();
 
-  // Update timing information for the current slice before we log it.
-  gCCStats.FinishCycleCollectionSlice();
-
   sCCollectedWaitingForGC += aResults.mFreedRefCounted + aResults.mFreedGCed;
 
   // If we collected a substantial amount of cycles, poke the GC since more objects
   // might be unreachable now.
   if (sCCollectedWaitingForGC > 250 ||
       sLikelyShortLivingObjectsNeedingGC > 2500 ||
       sNeedsGCAfterCC) {
     PokeGC(JS::gcreason::CC_WAITING);
   }
 
-  TimeStamp endCCTime = TimeStamp::Now();
+  PRTime endCCTime = PR_Now();
 
   // Log information about the CC via telemetry, JSON and the console.
   uint32_t ccNowDuration = TimeBetween(gCCStats.mBeginTime, endCCTime);
   Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_FINISH_IGC, gCCStats.mAnyLockedOut);
   Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_SYNC_SKIPPABLE, gCCStats.mRanSyncForgetSkippable);
   Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_FULL, ccNowDuration);
-  Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_MAX_PAUSE, gCCStats.mMaxSliceTime);
-
-  if (!sLastCCEndTime.IsNull()) {
+
+  if (sLastCCEndTime) {
     uint32_t timeBetween = TimeBetween(sLastCCEndTime, gCCStats.mBeginTime);
     Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_TIME_BETWEEN, timeBetween);
   }
   sLastCCEndTime = endCCTime;
 
   Telemetry::Accumulate(Telemetry::FORGET_SKIPPABLE_MAX,
                         sMaxForgetSkippableTime / PR_USEC_PER_MSEC);
 
@@ -2237,21 +2210,21 @@ nsJSContext::EndCycleCollectionCallback(
     }
 
     nsCString gcMsg;
     if (aResults.mForcedGC) {
       gcMsg.AssignLiteral(", forced a GC");
     }
 
     NS_NAMED_MULTILINE_LITERAL_STRING(kFmt,
-      MOZ_UTF16("CC(T+%.1f) max pause: %lums, total time: %lums, suspected: %lu, visited: %lu RCed and %lu%s GCed, collected: %lu RCed and %lu GCed (%lu|%lu waiting for GC)%s\n")
+      MOZ_UTF16("CC(T+%.1f) duration: %lums, suspected: %lu, visited: %lu RCed and %lu%s GCed, collected: %lu RCed and %lu GCed (%lu|%lu waiting for GC)%s\n")
       MOZ_UTF16("ForgetSkippable %lu times before CC, min: %lu ms, max: %lu ms, avg: %lu ms, total: %lu ms, max sync: %lu ms, removed: %lu"));
     nsString msg;
     msg.Adopt(nsTextFormatter::smprintf(kFmt.get(), double(delta) / PR_USEC_PER_SEC,
-                                        gCCStats.mMaxSliceTime, ccNowDuration, gCCStats.mSuspected,
+                                        ccNowDuration, gCCStats.mSuspected,
                                         aResults.mVisitedRefCounted, aResults.mVisitedGCed, mergeMsg.get(),
                                         aResults.mFreedRefCounted, aResults.mFreedGCed,
                                         sCCollectedWaitingForGC, sLikelyShortLivingObjectsNeedingGC,
                                         gcMsg.get(),
                                         sForgetSkippableBeforeCC,
                                         minForgetSkippableTime / PR_USEC_PER_MSEC,
                                         sMaxForgetSkippableTime / PR_USEC_PER_MSEC,
                                         (sTotalForgetSkippableTime / cleanups) /
@@ -2264,17 +2237,16 @@ nsJSContext::EndCycleCollectionCallback(
       cs->LogStringMessage(msg.get());
     }
   }
 
   if (sPostGCEventsToObserver) {
     NS_NAMED_MULTILINE_LITERAL_STRING(kJSONFmt,
        MOZ_UTF16("{ \"timestamp\": %llu, ")
          MOZ_UTF16("\"duration\": %llu, ")
-         MOZ_UTF16("\"max_slice_pause\": %llu, ")
          MOZ_UTF16("\"max_finish_gc_duration\": %llu, ")
          MOZ_UTF16("\"max_sync_skippable_duration\": %llu, ")
          MOZ_UTF16("\"suspected\": %lu, ")
          MOZ_UTF16("\"visited\": { ")
              MOZ_UTF16("\"RCed\": %lu, ")
              MOZ_UTF16("\"GCed\": %lu }, ")
          MOZ_UTF16("\"collected\": { ")
              MOZ_UTF16("\"RCed\": %lu, ")
@@ -2286,18 +2258,18 @@ nsJSContext::EndCycleCollectionCallback(
              MOZ_UTF16("\"times_before_cc\": %lu, ")
              MOZ_UTF16("\"min\": %lu, ")
              MOZ_UTF16("\"max\": %lu, ")
              MOZ_UTF16("\"avg\": %lu, ")
              MOZ_UTF16("\"total\": %lu, ")
              MOZ_UTF16("\"removed\": %lu } ")
        MOZ_UTF16("}"));
     nsString json;
-    json.Adopt(nsTextFormatter::smprintf(kJSONFmt.get(), endCCTime, ccNowDuration,
-                                         gCCStats.mMaxSliceTime, gCCStats.mMaxGCDuration,
+    json.Adopt(nsTextFormatter::smprintf(kJSONFmt.get(), endCCTime,
+                                         ccNowDuration, gCCStats.mMaxGCDuration,
                                          gCCStats.mMaxSkippableDuration,
                                          gCCStats.mSuspected,
                                          aResults.mVisitedRefCounted, aResults.mVisitedGCed,
                                          aResults.mFreedRefCounted, aResults.mFreedGCed,
                                          sCCollectedWaitingForGC,
                                          sLikelyShortLivingObjectsNeedingGC,
                                          aResults.mForcedGC,
                                          sForgetSkippableBeforeCC,
@@ -2357,17 +2329,17 @@ ShrinkGCBuffersTimerFired(nsITimer *aTim
 }
 
 static bool
 ShouldTriggerCC(uint32_t aSuspected)
 {
   return sNeedsFullCC ||
          aSuspected > NS_CC_PURPLE_LIMIT ||
          (aSuspected > NS_CC_FORCED_PURPLE_LIMIT &&
-          TimeUntilNow(sLastCCEndTime) > NS_CC_FORCED);
+          sLastCCEndTime + NS_CC_FORCED < PR_Now());
 }
 
 static uint32_t
 TimeToNextCC()
 {
   if (sIncrementalCC) {
     return NS_CC_DELAY - kMaxICCDuration;
   }
@@ -2779,17 +2751,17 @@ nsJSContext::LikelyShortLivingObjectCrea
 
 void
 mozilla::dom::StartupJSEnvironment()
 {
   // initialize all our statics, so that we can restart XPCOM
   sGCTimer = sFullGCTimer = sCCTimer = sICCTimer = nullptr;
   sCCLockedOut = false;
   sCCLockedOutTime = 0;
-  sLastCCEndTime = TimeStamp();
+  sLastCCEndTime = 0;
   sHasRunGC = false;
   sPendingLoadCount = 0;
   sLoadingInProgress = false;
   sCCollectedWaitingForGC = 0;
   sLikelyShortLivingObjectsNeedingGC = 0;
   sPostGCEventsToConsole = false;
   sNeedsFullCC = false;
   sNeedsGCAfterCC = false;
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -72,22 +72,16 @@
     "description": "Time spent on one cycle collection in a worker (ms)"
   },
   "CYCLE_COLLECTOR_FULL": {
     "kind": "exponential",
     "high": "10000",
     "n_buckets": 50,
     "description": "Full pause time for one cycle collection, including preparation (ms)"
   },
-  "CYCLE_COLLECTOR_MAX_PAUSE": {
-    "kind": "exponential",
-    "high": "10000",
-    "n_buckets": 50,
-    "description": "Longest pause for an individual slice of one cycle collection, including preparation (ms)"
-  },
   "CYCLE_COLLECTOR_FINISH_IGC": {
     "kind": "boolean",
     "description": "Cycle collection finished an incremental GC"
   },
   "CYCLE_COLLECTOR_SYNC_SKIPPABLE": {
     "kind": "boolean",
     "description": "Cycle collection synchronously ran forget skippable"
   },