Bug 1292600 - Add telemetry to measure how idle budgets are used. r=froydnj, data-r=bsmedberg
authorAndreas Farre <farre@mozilla.com>
Mon, 29 May 2017 19:45:33 +0200
changeset 362698 e5901d855fafdce064137ab1c72126e43b06c971
parent 362697 1ccbaeaf822e5a5539a6ee5b2330b7b906e31dff
child 362699 a61734b1fe8bfff1fd55f4b1835ffdf7e5bbcc7e
push id91158
push userafarre@mozilla.com
push dateWed, 07 Jun 2017 14:27:28 +0000
treeherdermozilla-inbound@e5901d855faf [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersfroydnj
bugs1292600
milestone55.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 1292600 - Add telemetry to measure how idle budgets are used. r=froydnj, data-r=bsmedberg
toolkit/components/telemetry/Histograms.json
xpcom/threads/nsThread.cpp
xpcom/threads/nsThread.h
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -13310,16 +13310,27 @@
     "expires_in_version": "60",
     "kind": "exponential",
     "low": 32,
     "high": 750,
     "n_buckets": 40,
     "keyed": true,
     "description": "Measures the number of milliseconds we spend processing sync IPC messages in the receiving process, keyed by message name. Note: only messages that take over 500 microseconds are included in this probe."
   },
+  "IDLE_RUNNABLE_BUDGET_OVERUSE_MS": {
+    "record_in_processes": ["main", "content", "gpu"],
+    "alert_emails": ["farre@mozilla.com"],
+    "expires_in_version": "60",
+    "kind": "exponential",
+    "keyed": true,
+    "high": 10000,
+    "n_buckets": 10,
+    "bug_numbers": [1292600],
+    "description": "The time a given runnable exceeds its budget as set in nsIRunnable::SetDeadline (in milliseconds). The key comes from the runnables nsINamed::name value."
+  },
   "WEBEXT_BACKGROUND_PAGE_LOAD_MS": {
     "record_in_processes": ["main"],
     "alert_emails": ["addons-dev-internal@mozilla.com"],
     "bug_numbers": [1353172],
     "expires_in_version": "60",
     "kind": "exponential",
     "releaseChannelCollection": "opt-out",
     "high": 60000,
--- a/xpcom/threads/nsThread.cpp
+++ b/xpcom/threads/nsThread.cpp
@@ -1219,31 +1219,43 @@ nsThread::GetIdleEvent(nsIRunnable** aEv
 
   mIdleEvents.GetEvent(false, aEvent, aProofOfLock);
 
   if (*aEvent) {
     nsCOMPtr<nsIIdleRunnable> idleEvent(do_QueryInterface(*aEvent));
     if (idleEvent) {
       idleEvent->SetDeadline(idleDeadline);
     }
+
+#ifndef RELEASE_OR_BETA
+    // Store the next idle deadline to be able to determine budget use
+    // in ProcessNextEvent.
+    mNextIdleDeadline = idleDeadline;
+#endif
   }
 }
 
 void
 nsThread::GetEvent(bool aWait, nsIRunnable** aEvent,
                    unsigned short* aPriority,
                    MutexAutoLock& aProofOfLock)
 {
   MOZ_ASSERT(PR_GetCurrentThread() == mThread);
   MOZ_ASSERT(aEvent);
 
   MakeScopeExit([&] {
     mHasPendingEventsPromisedIdleEvent = false;
   });
 
+#ifndef RELEASE_OR_BETA
+  // Clear mNextIdleDeadline so that it is possible to determine that
+  // we're running an idle runnable in ProcessNextEvent.
+  mNextIdleDeadline = TimeStamp();
+#endif
+
   // We'll try to get an event to execute in three stages.
   // [1] First we just try to get it from the regular queue without waiting.
   mEvents->GetEvent(false, aEvent, aPriority, aProofOfLock);
 
   // [2] If we didn't get an event from the regular queue, try to
   // get one from the idle queue
   if (!*aEvent) {
     // Since events in mEvents have higher priority than idle
@@ -1263,16 +1275,37 @@ nsThread::GetEvent(bool aWait, nsIRunnab
   // idle queue, then if we should wait for events we block on the
   // main queue until an event is available.
   // If we are shutting down, then do not wait for new events.
   if (!*aEvent && aWait) {
     mEvents->GetEvent(aWait, aEvent, aPriority, aProofOfLock);
   }
 }
 
+#ifndef RELEASE_OR_BETA
+static bool
+GetLabeledRunnableName(nsIRunnable* aEvent, nsACString& aName)
+{
+  bool labeled = false;
+  if (RefPtr<SchedulerGroup::Runnable> groupRunnable = do_QueryObject(aEvent)) {
+    labeled = true;
+    MOZ_ALWAYS_TRUE(NS_SUCCEEDED(groupRunnable->GetName(aName)));
+  } else if (nsCOMPtr<nsINamed> named = do_QueryInterface(aEvent)) {
+    MOZ_ALWAYS_TRUE(NS_SUCCEEDED(named->GetName(aName)));
+  } else {
+    aName.AssignLiteral("non-nsINamed runnable");
+  }
+  if (aName.IsEmpty()) {
+    aName.AssignLiteral("anonymous runnable");
+  }
+
+  return labeled;
+}
+#endif
+
 NS_IMETHODIMP
 nsThread::ProcessNextEvent(bool aMayWait, bool* aResult)
 {
   LOG(("THRD(%p) ProcessNextEvent [%u %u]\n", this, aMayWait,
        mNestedEventLoopDepth));
 
   if (NS_WARN_IF(PR_GetCurrentThread() != mThread)) {
     return NS_ERROR_NOT_SAME_THREAD;
@@ -1328,49 +1361,53 @@ nsThread::ProcessNextEvent(bool aMayWait
       MutexAutoLock lock(mLock);
       GetEvent(reallyWait, getter_AddRefs(event), &priority, lock);
     }
 
     *aResult = (event.get() != nullptr);
 
     if (event) {
       LOG(("THRD(%p) running [%p]\n", this, event.get()));
-#ifndef RELEASE_OR_BETA
-      Maybe<Telemetry::AutoTimer<Telemetry::MAIN_THREAD_RUNNABLE_MS>> timer;
-#endif
+
       if (MAIN_THREAD == mIsMainThread) {
         HangMonitor::NotifyActivity();
+      }
 
 #ifndef RELEASE_OR_BETA
+      Maybe<Telemetry::AutoTimer<Telemetry::MAIN_THREAD_RUNNABLE_MS>> timer;
+      Maybe<Telemetry::AutoTimer<Telemetry::IDLE_RUNNABLE_BUDGET_OVERUSE_MS>> idleTimer;
+
+      if ((MAIN_THREAD == mIsMainThread) || mNextIdleDeadline) {
         nsCString name;
-        bool labeled = false;
-        if (RefPtr<SchedulerGroup::Runnable> groupRunnable = do_QueryObject(event)) {
-          labeled = true;
-          MOZ_ALWAYS_TRUE(NS_SUCCEEDED(groupRunnable->GetName(name)));
-        } else if (nsCOMPtr<nsINamed> named = do_QueryInterface(event)) {
-          MOZ_ALWAYS_TRUE(NS_SUCCEEDED(named->GetName(name)));
-        } else {
-          name.AssignLiteral("non-nsINamed runnable");
-        }
-        if (name.IsEmpty()) {
-          name.AssignLiteral("anonymous runnable");
+        bool labeled = GetLabeledRunnableName(event, name);
+
+        if (MAIN_THREAD == mIsMainThread) {
+          timer.emplace(name);
+
+          // High-priority runnables are ignored here since they'll run right away
+          // even with the cooperative scheduler.
+          if (!labeled && priority == nsIRunnablePriority::PRIORITY_NORMAL) {
+            TimeStamp now = TimeStamp::Now();
+            double diff = (now - mLastUnlabeledRunnable).ToMilliseconds();
+            Telemetry::Accumulate(Telemetry::TIME_BETWEEN_UNLABELED_RUNNABLES_MS, diff);
+            mLastUnlabeledRunnable = now;
+          }
         }
 
-        // High-priority runnables are ignored here since they'll run right away
-        // even with the cooperative scheduler.
-        if (!labeled && priority == nsIRunnablePriority::PRIORITY_NORMAL) {
-          TimeStamp now = TimeStamp::Now();
-          double diff = (now - mLastUnlabeledRunnable).ToMilliseconds();
-          Telemetry::Accumulate(Telemetry::TIME_BETWEEN_UNLABELED_RUNNABLES_MS, diff);
-          mLastUnlabeledRunnable = now;
+        if (mNextIdleDeadline) {
+          // If we construct the AutoTimer with the deadline, then we'll
+          // compute TimeStamp::Now() - mNextIdleDeadline when
+          // accumulating telemetry.  If that is positive we've
+          // overdrawn our idle budget, if it's negative it will go in
+          // the 0 bucket of the histogram.
+          idleTimer.emplace(name, mNextIdleDeadline);
         }
+      }
+#endif
 
-        timer.emplace(name);
-#endif
-      }
       event->Run();
     } else if (aMayWait) {
       MOZ_ASSERT(ShuttingDown(),
                  "This should only happen when shutting down");
       rv = NS_ERROR_UNEXPECTED;
     }
   }
 
--- a/xpcom/threads/nsThread.h
+++ b/xpcom/threads/nsThread.h
@@ -279,16 +279,20 @@ protected:
   mozilla::TimeStamp mLastUnlabeledRunnable;
 
   // Set to true if this thread creates a JSRuntime.
   bool mCanInvokeJS;
   // Set to true if HasPendingEvents() has been called and returned true because
   // of a pending idle event.  This is used to remember to return that idle
   // event from GetIdleEvent() to ensure that HasPendingEvents() never lies.
   bool mHasPendingEventsPromisedIdleEvent;
+
+#ifndef RELEASE_OR_BETA
+  mozilla::TimeStamp mNextIdleDeadline;
+#endif
 };
 
 #if defined(XP_UNIX) && !defined(ANDROID) && !defined(DEBUG) && HAVE_UALARM \
   && defined(_GNU_SOURCE)
 # define MOZ_CANARY
 
 extern int sCanaryOutputFD;
 #endif