Bug 1372042 - Add telemetry about running collectors during idle time, r=mccr8
authorOlli Pettay <Olli.Pettay@helsinki.fi>
Wed, 14 Jun 2017 23:41:22 +0300
changeset 412811 0b0175f6dd5461bced946b2213106dc18440a448
parent 412810 29d1a9af2655b665a0a1b2eacbeaecdd6fbfbd9f
child 412812 9c5366883d69fec2bf728e718410e7b5034d17b5
push id7566
push usermtabara@mozilla.com
push dateWed, 02 Aug 2017 08:25:16 +0000
treeherdermozilla-beta@86913f512c3c [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmccr8
bugs1372042
milestone56.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 1372042 - Add telemetry about running collectors during idle time, r=mccr8
dom/base/nsJSEnvironment.cpp
toolkit/components/telemetry/Histograms.json
--- a/dom/base/nsJSEnvironment.cpp
+++ b/dom/base/nsJSEnvironment.cpp
@@ -222,16 +222,18 @@ static uint32_t sCompactOnUserInactiveDe
 static bool sIsCompactingOnUserInactive = false;
 
 // In testing, we call RunNextCollectorTimer() to ensure that the collectors are run more
 // aggressively than they would be in regular browsing. sExpensiveCollectorPokes keeps
 // us from triggering expensive full collections too frequently.
 static int32_t sExpensiveCollectorPokes = 0;
 static const int32_t kPokesBetweenExpensiveCollectorTriggers = 5;
 
+static TimeDuration sGCUnnotifiedTotalTime;
+
 // Return true if some meaningful work was done.
 typedef bool (*CollectorRunnerCallback) (TimeStamp aDeadline, void* aData);
 
 // Repeating callback runner for CC and GC.
 class CollectorRunner final : public IdleRunnable
 {
 public:
   static already_AddRefed<CollectorRunner>
@@ -1429,32 +1431,51 @@ FinishAnyIncrementalGC()
 
 static void
 FireForgetSkippable(uint32_t aSuspected, bool aRemoveChildless,
                     TimeStamp aDeadline)
 {
   AutoProfilerTracing
     tracing("CC", aDeadline.IsNull() ? "ForgetSkippable" : "IdleForgetSkippable");
   PRTime startTime = PR_Now();
+  TimeStamp startTimeStamp = TimeStamp::Now();
   FinishAnyIncrementalGC();
   bool earlyForgetSkippable =
     sCleanupsSinceLastGC < NS_MAJOR_FORGET_SKIPPABLE_CALLS;
   nsCycleCollector_forgetSkippable(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();
+  TimeDuration duration = now - startTimeStamp;
+  if (duration.ToSeconds()) {
+    TimeDuration idleDuration;
+    if (!aDeadline.IsNull()) {
+      if (aDeadline < now) {
+        // This slice overflowed the idle period.
+        idleDuration = aDeadline - startTimeStamp;
+      } else {
+        idleDuration = duration;
+      }
+    }
+
+    uint32_t percent =
+      uint32_t(idleDuration.ToSeconds() / duration.ToSeconds() * 100);
+    Telemetry::Accumulate(Telemetry::FORGET_SKIPPABLE_DURING_IDLE, percent);
+  }
 }
 
 MOZ_ALWAYS_INLINE
 static uint32_t
 TimeBetween(TimeStamp start, TimeStamp end)
 {
   MOZ_ASSERT(end >= start);
   return (uint32_t) ((end - start).ToMilliseconds());
@@ -1513,26 +1534,46 @@ struct CycleCollectorStats
     mSuspected = 0;
     mMaxSkippableDuration = 0;
     mMaxSliceTime = 0;
     mTotalSliceTime = 0;
     mAnyLockedOut = false;
     mExtraForgetSkippableCalls = 0;
   }
 
-  void PrepareForCycleCollectionSlice(int32_t aExtraForgetSkippableCalls = 0);
+  void PrepareForCycleCollectionSlice(TimeStamp aDeadline = TimeStamp(),
+                                      int32_t aExtraForgetSkippableCalls = 0);
 
   void FinishCycleCollectionSlice()
   {
     if (mBeginSliceTime.IsNull()) {
       // We already called this method from EndCycleCollectionCallback for this slice.
       return;
     }
 
     mEndSliceTime = TimeStamp::Now();
+    TimeDuration duration = mEndSliceTime - mBeginSliceTime;
+
+    if (duration.ToSeconds()) {
+      TimeDuration idleDuration;
+      if (!mIdleDeadline.IsNull()) {
+        if (mIdleDeadline < mEndSliceTime) {
+          // This slice overflowed the idle period.
+          idleDuration = mIdleDeadline - mBeginSliceTime;
+        } else {
+          idleDuration = duration;
+        }
+      }
+
+      uint32_t percent =
+        uint32_t(idleDuration.ToSeconds() / duration.ToSeconds() * 100);
+      Telemetry::Accumulate(Telemetry::CYCLE_COLLECTOR_SLICE_DURING_IDLE,
+                            percent);
+    }
+
     uint32_t sliceTime = TimeBetween(mBeginSliceTime, mEndSliceTime);
     mMaxSliceTime = std::max(mMaxSliceTime, sliceTime);
     mMaxSliceTimeSinceClear = std::max(mMaxSliceTimeSinceClear, sliceTime);
     mTotalSliceTime += sliceTime;
     mBeginSliceTime = TimeStamp();
     MOZ_ASSERT(mExtraForgetSkippableCalls == 0, "Forget to reset extra forget skippable calls?");
   }
 
@@ -1571,24 +1612,30 @@ struct CycleCollectorStats
 
   // True if we were locked out by the GC in any slice of the current CC.
   bool mAnyLockedOut;
 
   int32_t mExtraForgetSkippableCalls;
 
   // A file to dump CC activity to; set by MOZ_CCTIMER environment variable.
   FILE* mFile;
+
+  // In case CC slice was triggered during idle time, set to the end of the idle
+  // period.
+  TimeStamp mIdleDeadline;
 };
 
 CycleCollectorStats gCCStats;
 
 void
-CycleCollectorStats::PrepareForCycleCollectionSlice(int32_t aExtraForgetSkippableCalls)
+CycleCollectorStats::PrepareForCycleCollectionSlice(TimeStamp aDeadline,
+                                                    int32_t aExtraForgetSkippableCalls)
 {
   mBeginSliceTime = TimeStamp::Now();
+  mIdleDeadline = aDeadline;
 
   // Before we begin the cycle collection, make sure there is no active GC.
   if (sCCLockedOut) {
     mAnyLockedOut = true;
     FinishAnyIncrementalGC();
     uint32_t gcTime = TimeBetween(mBeginSliceTime, TimeStamp::Now());
     mMaxGCDuration = std::max(mMaxGCDuration, gcTime);
   }
@@ -1631,17 +1678,18 @@ nsJSContext::CycleCollectNow(nsICycleCol
 {
   if (!NS_IsMainThread()) {
     return;
   }
 
   PROFILER_LABEL("nsJSContext", "CycleCollectNow",
     js::ProfileEntry::Category::CC);
 
-  gCCStats.PrepareForCycleCollectionSlice(aExtraForgetSkippableCalls);
+  gCCStats.PrepareForCycleCollectionSlice(TimeStamp(),
+                                          aExtraForgetSkippableCalls);
   nsCycleCollector_collect(aListener);
   gCCStats.FinishCycleCollectionSlice();
 }
 
 //static
 void
 nsJSContext::RunCycleCollectorSlice(TimeStamp aDeadline)
 {
@@ -1650,17 +1698,17 @@ nsJSContext::RunCycleCollectorSlice(Time
   }
 
   AutoProfilerTracing
     tracing("CC", aDeadline.IsNull() ? "CCSlice" : "IdleCCSlice");
 
   PROFILER_LABEL("nsJSContext", "RunCycleCollectorSlice",
     js::ProfileEntry::Category::CC);
 
-  gCCStats.PrepareForCycleCollectionSlice();
+  gCCStats.PrepareForCycleCollectionSlice(aDeadline);
 
   // Decide how long we want to budget for this slice. By default,
   // use an unlimited budget.
   js::SliceBudget budget = js::SliceBudget::unlimited();
 
   if (sIncrementalCC) {
     int64_t baseBudget = kICCSliceBudget;
     if (!aDeadline.IsNull()) {
@@ -1941,23 +1989,47 @@ InterSliceGCRunnerFired(TimeStamp aDeadl
   // We use longer budgets when timer runs since that means
   // there hasn't been idle time recently and we may have significant amount
   // garbage to collect.
   int64_t budget = sActiveIntersliceGCBudget * 2;
   if (!aDeadline.IsNull()) {
     budget = int64_t((aDeadline - TimeStamp::Now()).ToMilliseconds());
   }
 
+  TimeStamp startTimeStamp = TimeStamp::Now();
+
   uintptr_t reason = reinterpret_cast<uintptr_t>(aData);
   nsJSContext::GarbageCollectNow(aData ?
                                    static_cast<JS::gcreason::Reason>(reason) :
                                    JS::gcreason::INTER_SLICE_GC,
                                  nsJSContext::IncrementalGC,
                                  nsJSContext::NonShrinkingGC,
                                  budget);
+
+  TimeDuration duration = sGCUnnotifiedTotalTime;
+  sGCUnnotifiedTotalTime = TimeDuration();
+
+  if (duration.ToSeconds()) {
+    TimeDuration idleDuration;
+    if (!aDeadline.IsNull()) {
+      TimeStamp now = TimeStamp::Now();
+      if (aDeadline < now) {
+        // This slice overflowed the idle period.
+        idleDuration = aDeadline - startTimeStamp;
+      } else {
+        // Note, we don't want to use duration here, since it may contain
+        // data also from JS engine triggered GC slices.
+        idleDuration = now - startTimeStamp;
+      }
+    }
+
+    uint32_t percent =
+      uint32_t(idleDuration.ToSeconds() / duration.ToSeconds() * 100);
+    Telemetry::Accumulate(Telemetry::GC_SLICE_DURING_IDLE, percent);
+  }
   return true;
 }
 
 // static
 void
 GCTimerFired(nsITimer *aTimer, void *aClosure)
 {
   nsJSContext::KillGCTimer();
@@ -2419,16 +2491,18 @@ DOMGCSliceCallback(JSContext* aCx, JS::G
 
       break;
     }
 
     case JS::GC_SLICE_BEGIN:
       break;
 
     case JS::GC_SLICE_END:
+      sGCUnnotifiedTotalTime +=
+        aDesc.lastSliceEnd(aCx) - aDesc.lastSliceStart(aCx);
 
       // Schedule another GC slice if the GC has more work to do.
       nsJSContext::KillInterSliceGCRunner();
       if (!sShuttingDown && !aDesc.isComplete_) {
         sInterSliceGCRunner =
           CollectorRunner::Create(InterSliceGCRunnerFired, NS_INTERSLICE_GC_DELAY,
                                   sActiveIntersliceGCBudget, false);
       }
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -862,16 +862,25 @@
     "record_in_processes": ["main", "content"],
     "alert_emails": ["dev-telemetry-gc-alerts@mozilla.org"],
     "expires_in_version": "never",
     "kind": "exponential",
     "high": 10000,
     "n_buckets": 50,
     "description": "Time spent on one asynchronous SnowWhite freeing (ms)"
   },
+  "CYCLE_COLLECTOR_SLICE_DURING_IDLE": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["dev-telemetry-gc-alerts@mozilla.org"],
+    "expires_in_version": "62",
+    "kind": "linear",
+    "high": 100,
+    "n_buckets": 50,
+    "description": "Percent of cycle collector slice done during idle time"
+  },
   "DEFERRED_FINALIZE_ASYNC": {
     "record_in_processes": ["main", "content"],
     "expires_in_version": "never",
     "kind": "exponential",
     "high": 10000,
     "n_buckets": 50,
     "description": "Pause time for asynchronous deferred finalization (ms)"
   },
@@ -918,16 +927,25 @@
     "record_in_processes": ["main", "content"],
     "alert_emails": ["dev-telemetry-gc-alerts@mozilla.org"],
     "expires_in_version": "never",
     "kind": "exponential",
     "high": 10000,
     "n_buckets": 50,
     "description": "Max time spent on one forget skippable (ms)"
   },
+  "FORGET_SKIPPABLE_DURING_IDLE": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["dev-telemetry-gc-alerts@mozilla.org"],
+    "expires_in_version": "62",
+    "kind": "linear",
+    "high": 100,
+    "n_buckets": 50,
+    "description": "Percent of the cycle collector's forget skippable done during idle time"
+  },
   "FULLSCREEN_TRANSITION_BLACK_MS": {
     "record_in_processes": ["main", "content"],
     "alert_emails": ["xquan@mozilla.com"],
     "expires_in_version": "never",
     "kind": "exponential",
     "low": 100,
     "high": 5000,
     "n_buckets": 50,
@@ -1184,16 +1202,25 @@
     "record_in_processes": ["main", "content"],
     "alert_emails": ["dev-telemetry-gc-alerts@mozilla.org"],
     "expires_in_version": "never",
     "kind": "enumerated",
     "n_values": 32,
     "bug_numbers": [1293262],
     "description": "How many objects groups were selected for pretenuring by a minor GC"
   },
+  "GC_SLICE_DURING_IDLE": {
+    "record_in_processes": ["main", "content"],
+    "alert_emails": ["dev-telemetry-gc-alerts@mozilla.org"],
+    "expires_in_version": "62",
+    "kind": "linear",
+    "high": 100,
+    "n_buckets": 50,
+    "description": "Percent of GC slice done during idle time"
+  },
   "GEOLOCATION_ACCURACY_EXPONENTIAL": {
     "record_in_processes": ["main", "content"],
     "expires_in_version": "default",
     "kind": "exponential",
     "high": 100000,
     "n_buckets": 50,
     "description": "Location accuracy"
   },