Bug 1351021 - Compute mean time between unlabeled (r=froydnj,data-r=bsmedberg)

Accumulates the time in between running unlabeled runnables in a histogram. This
measurement will be useful to see how much of a win the cooperative scheduler
will be, assuming we label no more runnables.

MozReview-Commit-ID: 9lgoGJcXLP9

toolkit/components/telemetry/Histograms.json

@@ -13072,5 +13072,15 @@
     "n_buckets": 100,
     "bug_numbers": [1345540],
     "description": "Time (ms) for the APZ handled wheel event spent in handlers."
+  },
+  "TIME_BETWEEN_UNLABELED_RUNNABLES_MS": {
+    "record_in_processes": ["content"],
+    "alert_emails": ["wmccloskey@mozilla.com"],
+    "expires_in_version": "60",
+    "kind": "exponential",
+    "high": 30000,
+    "n_buckets": 30,
+    "bug_numbers": [1351021],
+    "description": "Every time we run an unlabeled runnable, this histogram records the time (in ms) since the last unlabeled runnable ran."
   }
 }

xpcom/threads/nsThread.cpp

@@ -481,7 +481,7 @@ nsThread::ThreadFunc(void* aArg)
   nsCOMPtr<nsIRunnable> event;
   {
     MutexAutoLock lock(self->mLock);
-    if (!self->mEvents->GetEvent(true, getter_AddRefs(event), lock)) {
+    if (!self->mEvents->GetEvent(true, getter_AddRefs(event), nullptr, lock)) {
       NS_WARNING("failed waiting for thread startup event");
       return;
     }
@@ -642,6 +642,7 @@ nsThread::nsThread(MainThreadFlag aMainThread, uint32_t aStackSize)
   , mShutdownRequired(false)
   , mEventsAreDoomed(false)
   , mIsMainThread(aMainThread)
+  , mLastUnlabeledRunnable(TimeStamp::Now())
   , mCanInvokeJS(false)
 {
 }
@@ -809,6 +810,7 @@ nsThread::DispatchInternal(already_AddRefed<nsIRunnable> aEvent, uint32_t aFlags
 
 bool
 nsThread::nsChainedEventQueue::GetEvent(bool aMayWait, nsIRunnable** aEvent,
+                                        unsigned short* aPriority,
                                         mozilla::MutexAutoLock& aProofOfLock)
 {
   bool retVal = false;
@@ -817,6 +819,9 @@ nsThread::nsChainedEventQueue::GetEvent(bool aMayWait, nsIRunnable** aEvent,
       MOZ_ASSERT(mSecondaryQueue->HasPendingEvent(aProofOfLock));
       retVal = mSecondaryQueue->GetEvent(aMayWait, aEvent, aProofOfLock);
       MOZ_ASSERT(*aEvent);
+      if (aPriority) {
+        *aPriority = nsIRunnablePriority::PRIORITY_HIGH;
+      }
       mProcessSecondaryQueueRunnable = false;
       return retVal;
     }
@@ -826,6 +831,9 @@ nsThread::nsChainedEventQueue::GetEvent(bool aMayWait, nsIRunnable** aEvent,
       aMayWait && !mSecondaryQueue->HasPendingEvent(aProofOfLock);
     retVal =
       mNormalQueue->GetEvent(reallyMayWait, aEvent, aProofOfLock);
+    if (aPriority) {
+      *aPriority = nsIRunnablePriority::PRIORITY_NORMAL;
+    }
 
     // Let's see if we should next time process an event from the secondary
     // queue.
@@ -1157,14 +1165,16 @@ nsThread::GetIdleEvent(nsIRunnable** aEvent, MutexAutoLock& aProofOfLock)
 }
 
 void
-nsThread::GetEvent(bool aWait, nsIRunnable** aEvent, MutexAutoLock& aProofOfLock)
+nsThread::GetEvent(bool aWait, nsIRunnable** aEvent,
+                   unsigned short* aPriority,
+                   MutexAutoLock& aProofOfLock)
 {
   MOZ_ASSERT(PR_GetCurrentThread() == mThread);
   MOZ_ASSERT(aEvent);
 
   // 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, aProofOfLock);
+  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
@@ -1175,6 +1185,11 @@ nsThread::GetEvent(bool aWait, nsIRunnable** aEvent, MutexAutoLock& aProofOfLock
     // wait for an idle event, since a higher priority event might
     // appear at any time.
     GetIdleEvent(aEvent, aProofOfLock);
+
+    if (*aEvent && aPriority) {
+      // Idle events count as normal priority.
+      *aPriority = nsIRunnablePriority::PRIORITY_NORMAL;
+    }
   }
 
   // [3] If we neither got an event from the regular queue nor the
@@ -1182,7 +1197,7 @@ nsThread::GetEvent(bool aWait, nsIRunnable** aEvent, MutexAutoLock& aProofOfLock
   // 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, aProofOfLock);
+    mEvents->GetEvent(aWait, aEvent, aPriority, aProofOfLock);
   }
 }
 
@@ -1241,9 +1256,10 @@ nsThread::ProcessNextEvent(bool aMayWait, bool* aResult)
     // mNestedEventLoopDepth has been incremented, since that destructor can
     // also do work.
     nsCOMPtr<nsIRunnable> event;
+    unsigned short priority;
     {
       MutexAutoLock lock(mLock);
-      GetEvent(reallyWait, getter_AddRefs(event), lock);
+      GetEvent(reallyWait, getter_AddRefs(event), &priority, lock);
     }
 
     *aResult = (event.get() != nullptr);
@@ -1258,15 +1274,28 @@ nsThread::ProcessNextEvent(bool aMayWait, bool* aResult)
 
 #ifndef RELEASE_OR_BETA
         nsCString name;
-        if (nsCOMPtr<nsINamed> named = do_QueryInterface(event)) {
-          if (NS_FAILED(named->GetName(name))) {
-            name.AssignLiteral("GetName failed");
-          } else if (name.IsEmpty()) {
-            name.AssignLiteral("anonymous runnable");
-          }
+        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");
+        }
+
+        // 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;
+        }
+
         timer.emplace(name);
 #endif
       }
@@ -1461,7 +1490,7 @@ nsThread::PopEventQueue(nsIEventTarget* aInnermostTarget)
     mEvents = WrapNotNull(mEvents->mNext);
 
     nsCOMPtr<nsIRunnable> event;
-    while (queue->GetEvent(false, getter_AddRefs(event), lock)) {
+    while (queue->GetEvent(false, getter_AddRefs(event), nullptr, lock)) {
       mEvents->PutEvent(event.forget(), lock);
     }
 

xpcom/threads/nsThread.h

@@ -17,6 +17,7 @@
 #include "nsTObserverArray.h"
 #include "mozilla/Attributes.h"
 #include "mozilla/NotNull.h"
+#include "mozilla/TimeStamp.h"
 #include "nsAutoPtr.h"
 #include "mozilla/AlreadyAddRefed.h"
 #include "mozilla/UniquePtr.h"
@@ -98,6 +99,7 @@ private:
 
   void GetIdleEvent(nsIRunnable** aEvent, mozilla::MutexAutoLock& aProofOfLock);
   void GetEvent(bool aWait, nsIRunnable** aEvent,
+                unsigned short* aPriority,
                 mozilla::MutexAutoLock& aProofOfLock);
 
 protected:
@@ -154,6 +156,7 @@ protected:
     }
 
     bool GetEvent(bool aMayWait, nsIRunnable** aEvent,
+                  unsigned short* aPriority,
                   mozilla::MutexAutoLock& aProofOfLock);
 
     void PutEvent(nsIRunnable* aEvent, mozilla::MutexAutoLock& aProofOfLock)
@@ -270,6 +273,10 @@ protected:
   bool mEventsAreDoomed;
   MainThreadFlag mIsMainThread;
 
+  // The time when we last ran an unlabeled runnable (one not associated with a
+  // SchedulerGroup).
+  mozilla::TimeStamp mLastUnlabeledRunnable;
+
   // Set to true if this thread creates a JSRuntime.
   bool mCanInvokeJS;
 };