Bug 1580883 - Use TimeStamp/TimeDuration APIs instead of PRTime/PR_Now() in nsJSEnvironment.cpp r=mccr8
authorJon Coppeard <jcoppeard@mozilla.com>
Wed, 18 Sep 2019 12:48:09 +0000
changeset 493806 1d574f9c445735b1923eb2c8dff1c45051259890
parent 493805 29b8be50a6f48c6bd83644629944327ef057eccc
child 493807 2139d06ac9d2e3847e6d4d0b36dc11bfeb598811
push id95696
push userjcoppeard@mozilla.com
push dateWed, 18 Sep 2019 12:51:30 +0000
treeherderautoland@94c4e9a25f19 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmccr8
bugs1580883
milestone71.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 1580883 - Use TimeStamp/TimeDuration APIs instead of PRTime/PR_Now() in nsJSEnvironment.cpp r=mccr8 Differential Revision: https://phabricator.services.mozilla.com/D45693
dom/base/nsJSEnvironment.cpp
--- a/dom/base/nsJSEnvironment.cpp
+++ b/dom/base/nsJSEnvironment.cpp
@@ -132,18 +132,17 @@ static const int64_t kIdleICCSliceBudget
 static const uint32_t kMaxICCDuration = 2000;  // ms
 
 // Force a CC after this long if there's more than NS_CC_FORCED_PURPLE_LIMIT
 // objects in the purple buffer.
 static const uint32_t kCCForced = (2 * 60 * PR_USEC_PER_SEC);  // 2 min
 static const uint32_t kCCForcedPurpleLimit = 10;
 
 // Don't allow an incremental GC to lock out the CC for too long.
-static const int64_t kMaxCCLockedoutTime =
-    (30 * PR_USEC_PER_SEC);  // 30 seconds
+static const TimeDuration kMaxCCLockedoutTime = TimeDuration::FromSeconds(30);
 
 // Trigger a CC if the purple buffer exceeds this size when we check it.
 static const uint32_t kCCPurpleLimit = 200;
 
 // if you add statics here, add them to the list in StartupJSEnvironment
 
 static nsITimer* sGCTimer;
 static nsITimer* sShrinkingGCTimer;
@@ -154,40 +153,40 @@ static StaticRefPtr<IdleTaskRunner> sInt
 
 static TimeStamp sLastCCEndTime;
 
 static TimeStamp sLastForgetSkippableCycleEndTime;
 
 static TimeStamp sCurrentGCStartTime;
 
 static bool sCCLockedOut;
-static PRTime sCCLockedOutTime;
+static TimeStamp sCCLockedOutTime;
 
 static JS::GCSliceCallback sPrevGCSliceCallback;
 
 static bool sHasRunGC;
 
 static uint32_t sCCollectedWaitingForGC;
 static uint32_t sCCollectedZonesWaitingForGC;
 static uint32_t sLikelyShortLivingObjectsNeedingGC;
 static int32_t sCCRunnerFireCount = 0;
-static uint32_t sMinForgetSkippableTime = UINT32_MAX;
-static uint32_t sMaxForgetSkippableTime = 0;
-static uint32_t sTotalForgetSkippableTime = 0;
+static TimeDuration sMinForgetSkippableTime;
+static TimeDuration sMaxForgetSkippableTime;
+static TimeDuration sTotalForgetSkippableTime;
 static uint32_t sRemovedPurples = 0;
 static uint32_t sForgetSkippableBeforeCC = 0;
 static uint32_t sPreviousSuspectedCount = 0;
 static uint32_t sCleanupsSinceLastGC = UINT32_MAX;
 static bool sNeedsFullCC = false;
 static bool sNeedsFullGC = false;
 static bool sNeedsGCAfterCC = false;
 static bool sIncrementalCC = false;
 static int32_t sActiveIntersliceGCBudget = 5;  // ms;
 
-static PRTime sFirstCollectionTime;
+static TimeStamp sFirstCollectionTime;
 
 static bool sIsInitialized;
 static bool sDidShutdown;
 static bool sShuttingDown;
 
 // nsJSEnvironmentObserver observes the user-interaction-inactive notifications
 // and triggers a shrinking a garbage collection if the user is still inactive
 // after NS_SHRINKING_GC_DELAY ms later, if the appropriate pref is set.
@@ -275,23 +274,23 @@ void FindExceptionStackForConsoleReport(
     MOZ_ASSERT(JS::IsUnwrappedSavedFrame(stackObj));
     stackGlobal.set(JS::GetNonCCWObjectGlobal(stackObj));
     return;
   }
 }
 
 } /* namespace xpc */
 
-static PRTime GetCollectionTimeDelta() {
-  PRTime now = PR_Now();
+static TimeDuration GetCollectionTimeDelta() {
+  TimeStamp now = TimeStamp::Now();
   if (sFirstCollectionTime) {
     return now - sFirstCollectionTime;
   }
   sFirstCollectionTime = now;
-  return 0;
+  return TimeDuration();
 }
 
 static void KillTimers() {
   nsJSContext::KillGCTimer();
   nsJSContext::KillShrinkingGCTimer();
   nsJSContext::KillCCRunner();
   nsJSContext::KillICCRunner();
   nsJSContext::KillFullGCTimer();
@@ -1139,17 +1138,16 @@ static void FinishAnyIncrementalGC() {
   }
 }
 
 static void FireForgetSkippable(uint32_t aSuspected, bool aRemoveChildless,
                                 TimeStamp aDeadline) {
   AUTO_PROFILER_TRACING(
       "CC", aDeadline.IsNull() ? "ForgetSkippable" : "IdleForgetSkippable",
       GCCC);
-  PRTime startTime = PR_Now();
   TimeStamp startTimeStamp = TimeStamp::Now();
 
   static uint32_t sForgetSkippableCounter = 0;
   static TimeStamp sForgetSkippableFrequencyStartTime;
   static TimeStamp sLastForgetSkippableEndTime;
   static const TimeDuration minute = TimeDuration::FromSeconds(60.0f);
 
   if (sForgetSkippableFrequencyStartTime.IsNull()) {
@@ -1184,31 +1182,32 @@ static void FireForgetSkippable(uint32_t
           ? kForgetSkippableSliceDuration
           : int64_t((aDeadline - TimeStamp::Now()).ToMilliseconds());
   js::SliceBudget budget = js::SliceBudget(js::TimeBudget(budgetMs));
   nsCycleCollector_forgetSkippable(budget, aRemoveChildless,
                                    earlyForgetSkippable);
 
   sPreviousSuspectedCount = nsCycleCollector_suspectedCount();
   ++sCleanupsSinceLastGC;
-  PRTime delta = PR_Now() - startTime;
-  if (sMinForgetSkippableTime > delta) {
-    sMinForgetSkippableTime = delta;
-  }
-  if (sMaxForgetSkippableTime < delta) {
-    sMaxForgetSkippableTime = delta;
-  }
-  sTotalForgetSkippableTime += delta;
-  sRemovedPurples += (aSuspected - sPreviousSuspectedCount);
-  ++sForgetSkippableBeforeCC;
 
   TimeStamp now = TimeStamp::Now();
   sLastForgetSkippableEndTime = now;
 
   TimeDuration duration = now - startTimeStamp;
+
+  if (!sMinForgetSkippableTime || sMinForgetSkippableTime > duration) {
+    sMinForgetSkippableTime = duration;
+  }
+  if (!sMaxForgetSkippableTime || sMaxForgetSkippableTime < duration) {
+    sMaxForgetSkippableTime = duration;
+  }
+  sTotalForgetSkippableTime += duration;
+  sRemovedPurples += (aSuspected - sPreviousSuspectedCount);
+  ++sForgetSkippableBeforeCC;
+
   if (duration.ToSeconds()) {
     TimeDuration idleDuration;
     if (!aDeadline.IsNull()) {
       if (aDeadline < now) {
         // This slice overflowed the idle period.
         if (aDeadline > startTimeStamp) {
           idleDuration = aDeadline - startTimeStamp;
         }
@@ -1268,16 +1267,17 @@ struct CycleCollectorStats {
         MOZ_CRASH("Failed to open MOZ_CCTIMER log file.");
       }
     }
   }
 
   void Clear() {
     if (mFile && mFile != stdout && mFile != stderr) {
       fclose(mFile);
+      mFile = nullptr;
     }
     mBeginSliceTime = TimeStamp();
     mEndSliceTime = TimeStamp();
     mBeginTime = TimeStamp();
     mMaxGCDuration = 0;
     mRanSyncForgetSkippable = false;
     mSuspected = 0;
     mMaxSkippableDuration = 0;
@@ -1499,18 +1499,18 @@ static bool ICCRunnerFired(TimeStamp aDe
   if (sDidShutdown) {
     return false;
   }
 
   // Ignore ICC timer fires during IGC. Running ICC during an IGC will cause us
   // to synchronously finish the GC, which is bad.
 
   if (sCCLockedOut) {
-    PRTime now = PR_Now();
-    if (sCCLockedOutTime == 0) {
+    TimeStamp now = TimeStamp::Now();
+    if (!sCCLockedOutTime) {
       sCCLockedOutTime = now;
       return false;
     }
     if (now - sCCLockedOutTime < kMaxCCLockedoutTime) {
       return false;
     }
   }
 
@@ -1586,54 +1586,52 @@ void nsJSContext::EndCycleCollectionCall
     // TimeBetween returns milliseconds, but we want to report seconds.
     uint32_t timeBetween =
         TimeBetween(sLastCCEndTime, gCCStats.mBeginTime) / 1000;
     Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_TIME_BETWEEN, timeBetween);
   }
   sLastCCEndTime = endCCTimeStamp;
 
   Telemetry::Accumulate(Telemetry::FORGET_SKIPPABLE_MAX,
-                        sMaxForgetSkippableTime / PR_USEC_PER_MSEC);
-
-  PRTime delta = GetCollectionTimeDelta();
+                        sMaxForgetSkippableTime.ToMilliseconds());
+
+  TimeDuration delta = GetCollectionTimeDelta();
 
   uint32_t cleanups = sForgetSkippableBeforeCC ? sForgetSkippableBeforeCC : 1;
-  uint32_t minForgetSkippableTime =
-      (sMinForgetSkippableTime == UINT32_MAX) ? 0 : sMinForgetSkippableTime;
 
   if (StaticPrefs::javascript_options_mem_log() || gCCStats.mFile) {
     nsCString mergeMsg;
     if (aResults.mMergedZones) {
       mergeMsg.AssignLiteral(" merged");
     }
 
     nsCString gcMsg;
     if (aResults.mForcedGC) {
       gcMsg.AssignLiteral(", forced a GC");
     }
 
     const char16_t* kFmt =
         u"CC(T+%.1f)[%s-%i] max pause: %lums, total time: %lums, slices: %lu, "
         u"suspected: %lu, visited: %lu RCed and %lu%s GCed, collected: %lu "
         u"RCed and %lu GCed (%lu|%lu|%lu waiting for GC)%s\n"
-        u"ForgetSkippable %lu times before CC, min: %lu ms, max: %lu ms, avg: "
-        u"%lu ms, total: %lu ms, max sync: %lu ms, removed: %lu";
+        u"ForgetSkippable %lu times before CC, min: %.f ms, max: %.f ms, avg: "
+        u"%.f ms, total: %.f ms, max sync: %lu ms, removed: %lu";
     nsString msg;
     nsTextFormatter::ssprintf(
-        msg, kFmt, double(delta) / PR_USEC_PER_SEC,
+        msg, kFmt, delta.ToMicroseconds() / PR_USEC_PER_SEC,
         ProcessNameForCollectorLog(), getpid(), gCCStats.mMaxSliceTime,
         gCCStats.mTotalSliceTime, aResults.mNumSlices, gCCStats.mSuspected,
         aResults.mVisitedRefCounted, aResults.mVisitedGCed, mergeMsg.get(),
         aResults.mFreedRefCounted, aResults.mFreedGCed, sCCollectedWaitingForGC,
         sCCollectedZonesWaitingForGC, sLikelyShortLivingObjectsNeedingGC,
         gcMsg.get(), sForgetSkippableBeforeCC,
-        minForgetSkippableTime / PR_USEC_PER_MSEC,
-        sMaxForgetSkippableTime / PR_USEC_PER_MSEC,
-        (sTotalForgetSkippableTime / cleanups) / PR_USEC_PER_MSEC,
-        sTotalForgetSkippableTime / PR_USEC_PER_MSEC,
+        sMinForgetSkippableTime.ToMilliseconds(),
+        sMaxForgetSkippableTime.ToMilliseconds(),
+        sTotalForgetSkippableTime.ToMilliseconds() / cleanups,
+        sTotalForgetSkippableTime.ToMilliseconds(),
         gCCStats.mMaxSkippableDuration, sRemovedPurples);
     if (StaticPrefs::javascript_options_mem_log()) {
       nsCOMPtr<nsIConsoleService> cs =
           do_GetService(NS_CONSOLESERVICE_CONTRACTID);
       if (cs) {
         cs->LogStringMessage(msg.get());
       }
     }
@@ -1658,48 +1656,48 @@ void nsJSContext::EndCycleCollectionCall
         u"\"RCed\": %lu, "
         u"\"GCed\": %lu }, "
         u"\"waiting_for_gc\": %lu, "
         u"\"zones_waiting_for_gc\": %lu, "
         u"\"short_living_objects_waiting_for_gc\": %lu, "
         u"\"forced_gc\": %d, "
         u"\"forget_skippable\": { "
         u"\"times_before_cc\": %lu, "
-        u"\"min\": %lu, "
-        u"\"max\": %lu, "
-        u"\"avg\": %lu, "
-        u"\"total\": %lu, "
+        u"\"min\": %.f, "
+        u"\"max\": %.f, "
+        u"\"avg\": %.f, "
+        u"\"total\": %.f, "
         u"\"removed\": %lu } "
         u"}";
 
     nsString json;
     nsTextFormatter::ssprintf(
         json, kJSONFmt, PR_Now(), ccNowDuration, gCCStats.mMaxSliceTime,
         gCCStats.mTotalSliceTime, gCCStats.mMaxGCDuration,
         gCCStats.mMaxSkippableDuration, gCCStats.mSuspected,
         aResults.mVisitedRefCounted, aResults.mVisitedGCed,
         aResults.mFreedRefCounted, aResults.mFreedGCed, sCCollectedWaitingForGC,
         sCCollectedZonesWaitingForGC, sLikelyShortLivingObjectsNeedingGC,
         aResults.mForcedGC, sForgetSkippableBeforeCC,
-        minForgetSkippableTime / PR_USEC_PER_MSEC,
-        sMaxForgetSkippableTime / PR_USEC_PER_MSEC,
-        (sTotalForgetSkippableTime / cleanups) / PR_USEC_PER_MSEC,
-        sTotalForgetSkippableTime / PR_USEC_PER_MSEC, sRemovedPurples);
+        sMinForgetSkippableTime.ToMilliseconds(),
+        sMaxForgetSkippableTime.ToMilliseconds(),
+        sTotalForgetSkippableTime.ToMilliseconds() / cleanups,
+        sTotalForgetSkippableTime.ToMilliseconds(), sRemovedPurples);
     nsCOMPtr<nsIObserverService> observerService =
         mozilla::services::GetObserverService();
     if (observerService) {
       observerService->NotifyObservers(nullptr, "cycle-collection-statistics",
                                        json.get());
     }
   }
 
   // Update global state to indicate we have just run a cycle collection.
-  sMinForgetSkippableTime = UINT32_MAX;
-  sMaxForgetSkippableTime = 0;
-  sTotalForgetSkippableTime = 0;
+  sMinForgetSkippableTime = TimeDuration();
+  sMaxForgetSkippableTime = TimeDuration();
+  sTotalForgetSkippableTime = TimeDuration();
   sRemovedPurples = 0;
   sForgetSkippableBeforeCC = 0;
   sNeedsFullCC = false;
   sNeedsGCAfterCC = false;
   gCCStats.Clear();
 }
 
 // static
@@ -1708,20 +1706,20 @@ bool InterSliceGCRunnerFired(TimeStamp a
   // We use longer budgets when the CC has been locked out but the CC has tried
   // to run since that means we may have significant amount garbage to collect
   // and better to GC in several longer slices than in a very long one.
   int64_t budget =
       aDeadline.IsNull()
           ? int64_t(sActiveIntersliceGCBudget * 2)
           : int64_t((aDeadline - TimeStamp::Now()).ToMilliseconds());
   if (sCCLockedOut && sCCLockedOutTime) {
-    int64_t lockedTime = PR_Now() - sCCLockedOutTime;
+    TimeDuration lockedTime = TimeStamp::Now() - sCCLockedOutTime;
     int32_t maxSliceGCBudget = sActiveIntersliceGCBudget * 10;
     double percentOfLockedTime =
-        std::min((double)lockedTime / kMaxCCLockedoutTime, 1.0);
+        std::min(lockedTime / kMaxCCLockedoutTime, 1.0);
     budget = static_cast<int64_t>(
         std::max((double)budget, percentOfLockedTime * maxSliceGCBudget));
   }
 
   TimeStamp startTimeStamp = TimeStamp::Now();
   TimeDuration duration = sGCUnnotifiedTotalTime;
   uintptr_t reason = reinterpret_cast<uintptr_t>(aData);
   nsJSContext::GarbageCollectNow(
@@ -1799,18 +1797,18 @@ static bool CCRunnerFired(TimeStamp aDea
   if (sDidShutdown) {
     return false;
   }
 
   static uint32_t ccDelay = kCCDelay;
   if (sCCLockedOut) {
     ccDelay = kCCDelay / 3;
 
-    PRTime now = PR_Now();
-    if (sCCLockedOutTime == 0) {
+    TimeStamp now = TimeStamp::Now();
+    if (!sCCLockedOutTime) {
       // Reset sCCRunnerFireCount so that we run forgetSkippable
       // often enough before CC. Because of reduced ccDelay
       // forgetSkippable will be called just a few times.
       // kMaxCCLockedoutTime limit guarantees that we end up calling
       // forgetSkippable and CycleCollectNow eventually.
       sCCRunnerFireCount = 0;
       sCCLockedOutTime = now;
       return false;
@@ -2114,26 +2112,26 @@ void nsJSContext::KillShrinkingGCTimer()
   if (sShrinkingGCTimer) {
     sShrinkingGCTimer->Cancel();
     NS_RELEASE(sShrinkingGCTimer);
   }
 }
 
 // static
 void nsJSContext::KillCCRunner() {
-  sCCLockedOutTime = 0;
+  sCCLockedOutTime = TimeStamp();
   if (sCCRunner) {
     sCCRunner->Cancel();
     sCCRunner = nullptr;
   }
 }
 
 // static
 void nsJSContext::KillICCRunner() {
-  sCCLockedOutTime = 0;
+  sCCLockedOutTime = TimeStamp();
 
   if (sICCRunner) {
     sICCRunner->Cancel();
     sICCRunner = nullptr;
   }
 }
 
 class NotifyGCEndRunnable : public Runnable {
@@ -2173,24 +2171,24 @@ static void DOMGCSliceCallback(JSContext
     case JS::GC_CYCLE_BEGIN: {
       // Prevent cycle collections and shrinking during incremental GC.
       sCCLockedOut = true;
       sCurrentGCStartTime = TimeStamp::Now();
       break;
     }
 
     case JS::GC_CYCLE_END: {
-      PRTime delta = GetCollectionTimeDelta();
+      TimeDuration delta = GetCollectionTimeDelta();
 
       if (StaticPrefs::javascript_options_mem_log()) {
         nsString gcstats;
         gcstats.Adopt(aDesc.formatSummaryMessage(aCx));
         nsAutoString prefix;
         nsTextFormatter::ssprintf(prefix, u"GC(T+%.1f)[%s-%i] ",
-                                  double(delta) / PR_USEC_PER_SEC,
+                                  delta.ToSeconds(),
                                   ProcessNameForCollectorLog(), getpid());
         nsString msg = prefix + gcstats;
         nsCOMPtr<nsIConsoleService> cs =
             do_GetService(NS_CONSOLESERVICE_CONTRACTID);
         if (cs) {
           cs->LogStringMessage(msg.get());
         }
       }
@@ -2307,17 +2305,17 @@ JSObject* nsJSContext::GetWindowProxy() 
 void nsJSContext::LikelyShortLivingObjectCreated() {
   ++sLikelyShortLivingObjectsNeedingGC;
 }
 
 void mozilla::dom::StartupJSEnvironment() {
   // initialize all our statics, so that we can restart XPCOM
   sGCTimer = sShrinkingGCTimer = sFullGCTimer = nullptr;
   sCCLockedOut = false;
-  sCCLockedOutTime = 0;
+  sCCLockedOutTime = TimeStamp();
   sLastCCEndTime = TimeStamp();
   sLastForgetSkippableCycleEndTime = TimeStamp();
   sHasRunGC = false;
   sCCollectedWaitingForGC = 0;
   sCCollectedZonesWaitingForGC = 0;
   sLikelyShortLivingObjectsNeedingGC = 0;
   sNeedsFullCC = false;
   sNeedsFullGC = true;