Bug 1437438 - Add a performance counter to track scheduler activity - r=farre,froydnj

Adds a PeformanceCounter class that is used in DocGroup and WorkerPrivate
to track runnables execution and dispatch counts.

MozReview-Commit-ID: 51DLj6ORD2O

--HG--
extra : rebase_source : b481c9aa3b735569722bb7472872ec2d22adcb89

dom/base/DOMPrefsInternal.h

@@ -13,7 +13,7 @@
 //   * First argument is the name of the getter function.  This defines a
 //     DOMPrefs::FooBar()
 //   * The second argument is the name of the pref.
-// 
+//
 //   DOM_WEBIDL_PREF(FooBar)
 //
 //   * This defines DOMPrefs::FooBar(JSContext* aCx, JSObject* aObj);
@@ -23,6 +23,7 @@ DOM_PREF(ImageBitmapExtensionsEnabled, "canvas.imagebitmap_extensions.enabled")
 DOM_PREF(DOMCachesEnabled, "dom.caches.enabled")
 DOM_PREF(DOMCachesTestingEnabled, "dom.caches.testing.enabled")
 DOM_PREF(PerformanceLoggingEnabled, "dom.performance.enable_user_timing_logging")
+DOM_PREF(SchedulerLoggingEnabled, "dom.performance.enable_scheduler_timing")
 DOM_PREF(NotificationEnabled, "dom.webnotifications.enabled")
 DOM_PREF(NotificationEnabledInServiceWorkers, "dom.webnotifications.serviceworker.enabled")
 DOM_PREF(NotificationRIEnabled, "dom.webnotifications.requireinteraction.enabled")

dom/base/DocGroup.cpp

@@ -45,6 +45,9 @@ DocGroup::DocGroup(TabGroup* aTabGroup, const nsACString& aKey)
   : mKey(aKey), mTabGroup(aTabGroup)
 {
   // This method does not add itself to mTabGroup->mDocGroups as the caller does it for us.
+#ifndef RELEASE_OR_BETA
+  mPerformanceCounter = new mozilla::PerformanceCounter(aKey);
+#endif
 }
 
 DocGroup::~DocGroup()
@@ -62,6 +65,9 @@ nsresult
 DocGroup::Dispatch(TaskCategory aCategory,
                    already_AddRefed<nsIRunnable>&& aRunnable)
 {
+#ifndef RELEASE_OR_BETA
+  mPerformanceCounter->IncrementDispatchCounter(DispatchCategory(aCategory));
+#endif
   return mTabGroup->DispatchWithDocGroup(aCategory, Move(aRunnable), this);
 }
 

dom/base/DocGroup.h

@@ -16,6 +16,8 @@
 #include "mozilla/RefPtr.h"
 #include "mozilla/dom/CustomElementRegistry.h"
 #include "mozilla/dom/HTMLSlotElement.h"
+#include "mozilla/PerformanceCounter.h"
+
 
 namespace mozilla {
 class AbstractThread;
@@ -54,6 +56,12 @@ public:
   {
     return aKey == mKey;
   }
+#ifndef RELEASE_OR_BETA
+  PerformanceCounter* GetPerformanceCounter()
+  {
+    return mPerformanceCounter;
+  }
+#endif
   TabGroup* GetTabGroup()
   {
     return mTabGroup;
@@ -126,6 +134,9 @@ private:
   nsTArray<nsIDocument*> mDocuments;
   RefPtr<mozilla::dom::CustomElementReactionsStack> mReactionsStack;
   nsTArray<RefPtr<HTMLSlotElement>> mSignalSlotList;
+#ifndef RELEASE_OR_BETA
+  RefPtr<mozilla::PerformanceCounter> mPerformanceCounter;
+#endif
 };
 
 } // namespace dom

dom/ipc/ContentPrefs.cpp

@@ -72,6 +72,7 @@ const char* mozilla::dom::ContentPrefs::gEarlyPrefs[] = {
   "dom.max_script_run_time",
   "dom.mozBrowserFramesEnabled",
   "dom.performance.enable_notify_performance_timing",
+  "dom.performance.enable_scheduler_timing",
   "dom.performance.enable_user_timing_logging",
   "dom.placeholder.show_on_focus",
   "dom.requestIdleCallback.enabled",

dom/workers/WorkerPrivate.cpp

@@ -88,6 +88,9 @@ TimeoutsLog()
   return sWorkerTimeoutsLog;
 }
 
+#ifdef LOG
+#undef LOG
+#endif
 #define LOG(log, _args) MOZ_LOG(log, LogLevel::Debug, _args);
 
 namespace mozilla {
@@ -2616,6 +2619,9 @@ WorkerPrivate::WorkerPrivate(WorkerPrivate* aParent,
   , mIsSecureContext(false)
   , mDebuggerRegistered(false)
   , mIsInAutomation(false)
+#ifndef RELEASE_OR_BETA
+  , mPerformanceCounter(nullptr)
+#endif
 {
   MOZ_ASSERT_IF(!IsDedicatedWorker(), NS_IsMainThread());
   mLoadInfo.StealFrom(aLoadInfo);
@@ -5239,6 +5245,20 @@ WorkerPrivate::DumpCrashInformation(nsACString& aString)
   }
 }
 
+#ifndef RELEASE_OR_BETA
+PerformanceCounter*
+WorkerPrivate::GetPerformanceCounter()
+{
+  AssertIsOnWorkerThread();
+
+  if (!mPerformanceCounter) {
+    mPerformanceCounter = new PerformanceCounter(NS_ConvertUTF16toUTF8(mWorkerName));
+  }
+
+  return mPerformanceCounter;
+}
+#endif
+
 PerformanceStorage*
 WorkerPrivate::GetPerformanceStorage()
 {

dom/workers/WorkerPrivate.h

@@ -19,6 +19,7 @@
 #include "mozilla/dom/WorkerLoadInfo.h"
 #include "mozilla/dom/workerinternals/JSSettings.h"
 #include "mozilla/dom/workerinternals/Queue.h"
+#include "mozilla/PerformanceCounter.h"
 
 class nsIConsoleReportCollector;
 class nsIThreadInternal;
@@ -573,6 +574,11 @@ public:
   PerformanceStorage*
   GetPerformanceStorage();
 
+#ifndef RELEASE_OR_BETA
+  PerformanceCounter*
+  GetPerformanceCounter();
+#endif
+
   bool
   IsAcceptingEvents()
   {
@@ -1489,6 +1495,10 @@ private:
   // mIsInAutomation is true when we're running in test automation.
   // We expose some extra testing functions in that case.
   bool mIsInAutomation;
+
+#ifndef RELEASE_OR_BETA
+  RefPtr<mozilla::PerformanceCounter> mPerformanceCounter;
+#endif
 };
 
 class AutoSyncLoopHolder

dom/workers/WorkerThread.cpp

@@ -10,6 +10,7 @@
 #include "mozilla/ipc/BackgroundChild.h"
 #include "EventQueue.h"
 #include "mozilla/ThreadEventQueue.h"
+#include "mozilla/PerformanceCounter.h"
 #include "nsIThreadInternal.h"
 #include "WorkerPrivate.h"
 #include "WorkerRunnable.h"
@@ -227,6 +228,15 @@ WorkerThread::Dispatch(already_AddRefed<nsIRunnable> aRunnable, uint32_t aFlags)
 
   const bool onWorkerThread = PR_GetCurrentThread() == mThread;
 
+#ifndef RELEASE_OR_BETA
+  if (GetSchedulerLoggingEnabled() && onWorkerThread && mWorkerPrivate) {
+    PerformanceCounter* performanceCounter = mWorkerPrivate->GetPerformanceCounter();
+    if (performanceCounter) {
+      performanceCounter->IncrementDispatchCounter(DispatchCategory::Worker);
+    }
+  }
+#endif
+
 #ifdef DEBUG
   if (runnable && !onWorkerThread) {
     nsCOMPtr<nsICancelableRunnable> cancelable = do_QueryInterface(runnable);
@@ -314,6 +324,17 @@ WorkerThread::RecursionDepth(const WorkerThreadFriendKey& /* aKey */) const
   return mNestedEventLoopDepth;
 }
 
+#ifndef RELEASE_OR_BETA
+PerformanceCounter*
+WorkerThread::GetPerformanceCounter(nsIRunnable* aEvent)
+{
+  if (mWorkerPrivate) {
+    return mWorkerPrivate->GetPerformanceCounter();
+  }
+  return nullptr;
+}
+#endif
+
 NS_IMPL_ISUPPORTS(WorkerThread::Observer, nsIThreadObserver)
 
 NS_IMETHODIMP

dom/workers/WorkerThread.h

@@ -81,6 +81,11 @@ public:
   uint32_t
   RecursionDepth(const WorkerThreadFriendKey& aKey) const;
 
+#ifndef RELEASE_OR_BETA
+  PerformanceCounter*
+  GetPerformanceCounter(nsIRunnable* aEvent) override;
+#endif
+
   NS_INLINE_DECL_REFCOUNTING_INHERITED(WorkerThread, nsThread)
 
 private:

modules/libpref/init/all.js

@@ -196,6 +196,9 @@ pref("dom.performance.enable_user_timing_logging", false);
 // Enable notification of performance timing
 pref("dom.performance.enable_notify_performance_timing", false);
 
+// Enable collecting of docgroup activity in the scheduler
+pref("dom.performance.enable_scheduler_timing", false);
+
 // Enable Permission API's .revoke() method
 pref("dom.permissions.revoke.enable", false);
 

xpcom/tests/gtest/TestThreadMetrics.cpp

@@ -0,0 +1,200 @@
+/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
+/* vim: set ts=8 sts=2 et sw=2 tw=80: */
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+#include "gtest/gtest.h"
+#include "gmock/gmock.h"
+#include "mozilla/AbstractThread.h"
+#include "mozilla/Preferences.h"
+#include "mozilla/dom/DocGroup.h"
+#include "mozilla/dom/TabGroup.h"
+#include "mozilla/SchedulerGroup.h"
+#include "mozilla/TaskCategory.h"
+#include "mozilla/PerformanceCounter.h"
+#include "nsThreadUtils.h"
+#include "nsServiceManagerUtils.h"
+
+using namespace mozilla;
+using mozilla::Runnable;
+
+
+class MockSchedulerGroup: public SchedulerGroup
+{
+public:
+  explicit MockSchedulerGroup(mozilla::dom::DocGroup* aDocGroup)
+      : mDocGroup(aDocGroup) {}
+  NS_INLINE_DECL_REFCOUNTING(MockSchedulerGroup);
+
+  MOCK_METHOD1(SetValidatingAccess, void(ValidationType aType));
+  mozilla::dom::DocGroup* DocGroup() {
+    return mDocGroup;
+  }
+protected:
+  virtual ~MockSchedulerGroup() = default;
+private:
+
+  mozilla::dom::DocGroup* mDocGroup;
+};
+
+
+typedef testing::NiceMock<MockSchedulerGroup> MSchedulerGroup;
+
+/* Timed runnable which simulates some execution time
+ * and can run a nested runnable.
+ */
+class TimedRunnable final : public Runnable
+{
+public:
+  explicit TimedRunnable(uint32_t aExecutionTime1, uint32_t aExecutionTime2,
+                         bool aRecursive)
+    : Runnable("TimedRunnable")
+    , mExecutionTime1(aExecutionTime1)
+    , mExecutionTime2(aExecutionTime2)
+    , mRecursive(aRecursive)
+  {
+  }
+  NS_IMETHODIMP Run()
+  {
+    PR_Sleep(PR_MillisecondsToInterval(mExecutionTime1 + 5));
+    if (mRecursive) {
+      // Dispatch another runnable so nsThread::ProcessNextEvent is called recursively
+      nsCOMPtr<nsIThread> thread = do_GetMainThread();
+      nsCOMPtr<nsIRunnable> runnable = new TimedRunnable(155, 0, false);
+      thread->Dispatch(runnable, NS_DISPATCH_NORMAL);
+      (void)NS_ProcessNextEvent(thread, false);
+    }
+    PR_Sleep(PR_MillisecondsToInterval(mExecutionTime2 + 5));
+    return NS_OK;
+  }
+private:
+  uint32_t                    mExecutionTime1;
+  uint32_t                    mExecutionTime2;
+  bool                        mRecursive;
+};
+
+
+/* test class used for all metrics tests
+ *
+ * - sets up the enable_scheduler_timing pref
+ * - provides a function to dispatch runnables and spin the loop
+ */
+
+static const char prefKey[] = "dom.performance.enable_scheduler_timing";
+
+class ThreadMetrics: public ::testing::Test
+{
+public:
+  explicit ThreadMetrics() = default;
+
+protected:
+  virtual void SetUp() {
+    mOldPref = Preferences::GetBool(prefKey);
+    Preferences::SetBool(prefKey, true);
+    // building the TabGroup/DocGroup structure
+    nsCString key = NS_LITERAL_CSTRING("key");
+    nsCOMPtr<nsIDocument> doc;
+    RefPtr<mozilla::dom::TabGroup> tabGroup = new mozilla::dom::TabGroup(false);
+    mDocGroup = tabGroup->AddDocument(key, doc);
+    mSchedulerGroup = new MSchedulerGroup(mDocGroup);
+    mCounter = mDocGroup->GetPerformanceCounter();
+    mThreadMgr = do_GetService("@mozilla.org/thread-manager;1");
+    mOther = DispatchCategory(TaskCategory::Other).GetValue();
+    mDispatchCount = (uint32_t)TaskCategory::Other + 1;
+  }
+
+  virtual void TearDown() {
+    // let's reset the counters
+    mCounter->ResetPerformanceCounters();
+    for (uint32_t i = 0; i < mDispatchCount; i++) {
+      ASSERT_EQ(mCounter->GetDispatchCounter()[i], 0u);
+    }
+    ASSERT_EQ(mCounter->GetExecutionDuration(), 0u);
+    // and remove the document from the doc group (actually, a nullptr)
+    mDocGroup->RemoveDocument(nullptr);
+    mDocGroup = nullptr;
+    Preferences::SetBool(prefKey, mOldPref);
+  }
+
+  nsresult Dispatch(uint32_t aExecutionTime1, uint32_t aExecutionTime2,
+                    bool aRecursive) {
+    nsCOMPtr<nsIRunnable> runnable = new TimedRunnable(aExecutionTime1,
+                                                       aExecutionTime2,
+                                                       aRecursive);
+    runnable = new SchedulerGroup::Runnable(runnable.forget(),
+                                            mSchedulerGroup, mDocGroup);
+    return mDocGroup->Dispatch(TaskCategory::Other, runnable.forget());
+  }
+
+  void ProcessAllEvents() {
+    mThreadMgr->SpinEventLoopUntilEmpty();
+  }
+
+  uint32_t mOther;
+  bool mOldPref;
+  RefPtr<MSchedulerGroup> mSchedulerGroup;
+  RefPtr<mozilla::dom::DocGroup> mDocGroup;
+  RefPtr<mozilla::PerformanceCounter> mCounter;
+  nsCOMPtr<nsIThreadManager> mThreadMgr;
+  uint32_t mDispatchCount;
+};
+
+
+TEST_F(ThreadMetrics, CollectMetrics)
+{
+  nsresult rv;
+
+  // Dispatching a runnable that will last for +100ms
+  rv = Dispatch(100, 0, false);
+  ASSERT_TRUE(NS_SUCCEEDED(rv));
+
+  // Flush the queue
+  ProcessAllEvents();
+
+  // Let's look at the task category "other" counter
+  ASSERT_EQ(mCounter->GetDispatchCounter()[mOther], 1u);
+
+  // other counters should stay empty
+  for (uint32_t i = 0; i < mDispatchCount; i++) {
+    if (i != mOther) {
+        ASSERT_EQ(mCounter->GetDispatchCounter()[i], 0u);
+    }
+  }
+
+  // Did we get incremented in the docgroup ?
+  uint64_t duration = mCounter->GetExecutionDuration();
+  ASSERT_GE(duration, 100000u);
+  ASSERT_LT(duration, 150000u);
+}
+
+
+TEST_F(ThreadMetrics, CollectRecursiveMetrics)
+{
+  nsresult rv;
+
+  // Dispatching a runnable that will last for +100ms
+  // and run another one recursively
+  rv = Dispatch(50, 50, true);
+  ASSERT_TRUE(NS_SUCCEEDED(rv));
+
+  // Flush the queue
+  ProcessAllEvents();
+
+  // let's look at the counters
+  ASSERT_EQ(mCounter->GetDispatchCounter()[mOther], 1u);
+
+  // other counters should stay empty
+  for (uint32_t i = 0; i < mDispatchCount; i++) {
+    if (i != mOther) {
+        ASSERT_EQ(mCounter->GetDispatchCounter()[i], 0u);
+    }
+  }
+
+  // did we get incremented in the docgroup ?
+  uint64_t duration = mCounter->GetExecutionDuration();
+  ASSERT_GE(duration, 100000u);
+
+  // let's make sure we don't count the time spent in recursive calls
+  ASSERT_LT(duration, 150000u);
+}

xpcom/tests/gtest/moz.build

@@ -51,6 +51,7 @@ UNIFIED_SOURCES += [
     'TestTaskQueue.cpp',
     'TestTextFormatter.cpp',
     'TestThreadManager.cpp',
+    'TestThreadMetrics.cpp',
     'TestThreadPool.cpp',
     'TestThreadPoolListener.cpp',
     'TestThreads.cpp',

xpcom/threads/PerformanceCounter.cpp

@@ -0,0 +1,75 @@
+/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
+/* vim: set ts=8 sts=2 et sw=2 tw=80: */
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+#include "mozilla/Logging.h"
+#include "mozilla/PerformanceCounter.h"
+
+static mozilla::LazyLogModule sPerformanceCounter("PerformanceCounter");
+#ifdef LOG
+#undef LOG
+#endif
+#define LOG(args) MOZ_LOG(sPerformanceCounter, mozilla::LogLevel::Debug, args)
+
+// this instance is the extension for the worker
+const DispatchCategory DispatchCategory::Worker = DispatchCategory((uint32_t)TaskCategory::Count);
+
+PerformanceCounter::PerformanceCounter(const nsACString& aName)
+  : mExecutionDuration(0),
+    mTotalDispatchCount(0),
+    mDispatchCounter(),
+    mName(aName)
+{
+  ResetPerformanceCounters();
+}
+
+void
+PerformanceCounter::IncrementDispatchCounter(DispatchCategory aCategory)
+{
+  mDispatchCounter[aCategory.GetValue()] += 1;
+  mTotalDispatchCount += 1;
+  LOG(("[%s] Total dispatch %" PRIu64, mName.get(), uint64_t(mTotalDispatchCount)));
+}
+
+void
+PerformanceCounter::IncrementExecutionDuration(uint32_t aMicroseconds)
+{
+  mExecutionDuration += aMicroseconds;
+  LOG(("[%s] Total duration %" PRIu64, mName.get(), uint64_t(mExecutionDuration)));
+}
+
+const DispatchCounter&
+PerformanceCounter::GetDispatchCounter()
+{
+  return mDispatchCounter;
+}
+
+uint64_t
+PerformanceCounter::GetExecutionDuration()
+{
+  return mExecutionDuration;
+}
+
+uint64_t
+PerformanceCounter::GetTotalDispatchCount()
+{
+  return mTotalDispatchCount;
+}
+
+uint32_t
+PerformanceCounter::GetDispatchCount(DispatchCategory aCategory)
+{
+  return mDispatchCounter[aCategory.GetValue()];
+}
+
+void
+PerformanceCounter::ResetPerformanceCounters()
+{
+  for (auto& cnt : mDispatchCounter) {
+    cnt = 0;
+  }
+  mExecutionDuration = 0;
+  mTotalDispatchCount = 0;
+}

xpcom/threads/PerformanceCounter.h

@@ -0,0 +1,128 @@
+/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
+/* vim: set ts=8 sts=2 et sw=2 tw=80: */
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+#ifndef mozilla_PerformanceCounter_h
+#define mozilla_PerformanceCounter_h
+
+namespace mozilla {
+
+
+/*
+ * The DispatchCategory class is used to fake the inheritance
+ * of the TaskCategory enum so we can extend it to hold
+ * one more value corresponding to the category
+ * we use when a worker dispatches a call.
+ *
+ */
+class DispatchCategory final
+{
+public:
+  explicit DispatchCategory(uint32_t aValue)
+    : mValue(aValue)
+  {
+    // Since DispatchCategory is adding one single value to the
+    // TaskCategory enum, we can check here that the value is
+    // the next index e.g. TaskCategory::Count
+    MOZ_ASSERT(aValue == (uint32_t)TaskCategory::Count);
+  }
+
+  constexpr explicit DispatchCategory(TaskCategory aValue)
+    : mValue((uint32_t)aValue)
+  {}
+
+  uint32_t
+  GetValue() const
+  {
+    return mValue;
+  }
+
+  static const DispatchCategory Worker;
+private:
+  uint32_t mValue;
+};
+
+typedef Array<Atomic<uint32_t>, (uint32_t)TaskCategory::Count + 1> DispatchCounter;
+
+// PerformanceCounter is a class that can be used to keep track of
+// runnable execution times and dispatch counts.
+//
+// - runnable execution time: time spent in a runnable when called
+//   in nsThread::ProcessNextEvent (not counting recursive calls)
+// - dispatch counts: number of times a tracked runnable is dispatched
+//   in nsThread. Useful to measure the activity of a tab or worker.
+//
+// The PerformanceCounter class is currently instantiated in DocGroup
+// and WorkerPrivate in order to count how many scheduler dispatches
+// are done through them, and how long the execution lasts.
+//
+// The execution time is calculated by the nsThread class (and its
+// inherited WorkerThread class) in its ProcessNextEvent method.
+//
+// For each processed runnable, nsThread will reach out the
+// PerformanceCounter attached to the runnable via its DocGroup
+// or WorkerPrivate and call IncrementExecutionDuration()
+//
+// Notice that the execution duration counting takes into account
+// recursivity. If an event triggers a recursive call to
+// nsThread::ProcessNextEVent, the counter will discard the time
+// spent in sub events.
+class PerformanceCounter final
+{
+public:
+  NS_INLINE_DECL_THREADSAFE_REFCOUNTING(PerformanceCounter)
+
+  explicit PerformanceCounter(const nsACString& aName);
+
+  /**
+   * This is called everytime a runnable is dispatched.
+   *
+   * aCategory can be used to distinguish counts per TaskCategory
+   */
+  void IncrementDispatchCounter(DispatchCategory aCategory);
+
+  /**
+   * This is called via nsThread::ProcessNextEvent to measure runnable
+   * execution duration.
+   */
+  void IncrementExecutionDuration(uint32_t aMicroseconds);
+
+  /**
+   * Returns a category/counter array of all dispatches.
+   */
+  const DispatchCounter& GetDispatchCounter();
+
+  /**
+   * Returns the total execution duration.
+   */
+  uint64_t GetExecutionDuration();
+
+  /**
+   * Returns the number of dispatches per TaskCategory.
+   */
+  uint32_t GetDispatchCount(DispatchCategory aCategory);
+
+  /**
+   * Returns the total number of dispatches.
+   */
+  uint64_t GetTotalDispatchCount();
+
+  /**
+   * Reset all counters and execution duration.
+   */
+  void ResetPerformanceCounters();
+
+private:
+  ~PerformanceCounter() {}
+
+  Atomic<uint64_t> mExecutionDuration;
+  Atomic<uint64_t> mTotalDispatchCount;
+  DispatchCounter mDispatchCounter;
+  nsCString mName;
+};
+
+} // namespace mozilla
+
+#endif // mozilla_PerformanceCounter_h

xpcom/threads/moz.build

@@ -52,6 +52,7 @@ EXPORTS.mozilla += [
     'Monitor.h',
     'MozPromise.h',
     'Mutex.h',
+    'PerformanceCounter.h',
     'Queue.h',
     'RecursiveMutex.h',
     'ReentrantMonitor.h',
@@ -97,6 +98,7 @@ UNIFIED_SOURCES += [
     'nsThreadPool.cpp',
     'nsThreadUtils.cpp',
     'nsTimerImpl.cpp',
+    'PerformanceCounter.cpp',
     'PrioritizedEventQueue.cpp',
     'RecursiveMutex.cpp',
     'RWLock.cpp',

xpcom/threads/nsThread.cpp

@@ -28,6 +28,7 @@
 #include "mozilla/IOInterposer.h"
 #include "mozilla/ipc/MessageChannel.h"
 #include "mozilla/ipc/BackgroundChild.h"
+#include "mozilla/Preferences.h"
 #include "mozilla/Scheduler.h"
 #include "mozilla/SchedulerGroup.h"
 #include "mozilla/Services.h"
@@ -46,6 +47,7 @@
 #include "ThreadEventTarget.h"
 
 #include "mozilla/dom/ContentChild.h"
+#include "mozilla/dom/DOMPrefs.h"
 
 #ifdef XP_LINUX
 #include <sys/time.h>
@@ -558,6 +560,12 @@ nsThread::nsThread(NotNull<SynchronizedEventQueue*> aQueue,
   , mIsMainThread(aMainThread)
   , mLastUnlabeledRunnable(TimeStamp::Now())
   , mCanInvokeJS(false)
+#ifndef RELEASE_OR_BETA
+  , mCurrentEvent(nullptr)
+  , mCurrentEventStart(TimeStamp::Now())
+  , mCurrentEventLoopDepth(-1)
+  , mCurrentPerformanceCounter(nullptr)
+#endif
 {
 }
 
@@ -578,6 +586,16 @@ nsThread::~nsThread()
 #endif
 }
 
+#ifndef RELEASE_OR_BETA
+bool
+nsThread::GetSchedulerLoggingEnabled() {
+  if (!NS_IsMainThread() || !mozilla::Preferences::IsServiceAvailable()) {
+    return false;
+  }
+  return mozilla::dom::DOMPrefs::SchedulerLoggingEnabled();
+}
+#endif
+
 nsresult
 nsThread::Init(const nsACString& aName)
 {
@@ -907,6 +925,20 @@ GetLabeledRunnableName(nsIRunnable* aEvent,
 
   return labeled;
 }
+
+mozilla::PerformanceCounter*
+nsThread::GetPerformanceCounter(nsIRunnable* aEvent)
+{
+  RefPtr<SchedulerGroup::Runnable> docRunnable = do_QueryObject(aEvent);
+  if (docRunnable) {
+    mozilla::dom::DocGroup* docGroup = docRunnable->DocGroup();
+    if (docGroup) {
+      return docGroup->GetPerformanceCounter();
+    }
+  }
+  return nullptr;
+}
+
 #endif
 
 NS_IMETHODIMP
@@ -980,6 +1012,16 @@ nsThread::ProcessNextEvent(bool aMayWait, bool* aResult)
       }
 
 #ifndef RELEASE_OR_BETA
+      bool schedulerLoggingEnabled = GetSchedulerLoggingEnabled();
+      if (schedulerLoggingEnabled
+          && mNestedEventLoopDepth > mCurrentEventLoopDepth
+          && mCurrentPerformanceCounter) {
+          // This is a recursive call, we're saving the time
+          // spent in the parent event if the runnable is linked to a DocGroup.
+          mozilla::TimeDuration duration = TimeStamp::Now() - mCurrentEventStart;
+          mCurrentPerformanceCounter->IncrementExecutionDuration(duration.ToMicroseconds());
+      }
+
       Maybe<Telemetry::AutoTimer<Telemetry::MAIN_THREAD_RUNNABLE_MS>> timer;
       Maybe<Telemetry::AutoTimer<Telemetry::IDLE_RUNNABLE_BUDGET_OVERUSE_MS>> idleTimer;
 
@@ -1037,7 +1079,42 @@ nsThread::ProcessNextEvent(bool aMayWait, bool* aResult)
       if (priority == EventPriority::Input) {
         timeDurationHelper.emplace();
       }
+
+#ifndef RELEASE_OR_BETA
+      // The event starts to run, storing the timestamp.
+      bool recursiveEvent = false;
+      RefPtr<mozilla::PerformanceCounter> currentPerformanceCounter;
+      if (schedulerLoggingEnabled) {
+        recursiveEvent = mNestedEventLoopDepth > mCurrentEventLoopDepth;
+        mCurrentEventStart = mozilla::TimeStamp::Now();
+        mCurrentEvent = event;
+        mCurrentEventLoopDepth = mNestedEventLoopDepth;
+        mCurrentPerformanceCounter = GetPerformanceCounter(event);
+        currentPerformanceCounter = mCurrentPerformanceCounter;
+      }
+#endif
       event->Run();
+
+#ifndef RELEASE_OR_BETA
+      // End of execution, we can send the duration for the group
+      if (schedulerLoggingEnabled) {
+       if (recursiveEvent) {
+          // If we're in a recursive call, reset the timer,
+          // so the parent gets its remaining execution time right.
+          mCurrentEventStart = mozilla::TimeStamp::Now();
+          mCurrentPerformanceCounter = currentPerformanceCounter;
+        } else {
+          // We're done with this dispatch
+          if (currentPerformanceCounter) {
+            mozilla::TimeDuration duration = TimeStamp::Now() - mCurrentEventStart;
+            currentPerformanceCounter->IncrementExecutionDuration(duration.ToMicroseconds());
+          }
+          mCurrentEvent = nullptr;
+          mCurrentEventLoopDepth = -1;
+          mCurrentPerformanceCounter = nullptr;
+        }
+      }
+#endif
     } else if (aMayWait) {
       MOZ_ASSERT(ShuttingDown(),
                  "This should only happen when shutting down");

xpcom/threads/nsThread.h

@@ -22,6 +22,7 @@
 #include "mozilla/AlreadyAddRefed.h"
 #include "mozilla/UniquePtr.h"
 #include "mozilla/Array.h"
+#include "mozilla/dom/DocGroup.h"
 
 namespace mozilla {
 class CycleCollectedJSContext;
@@ -129,6 +130,10 @@ public:
     return mShutdownContext != nullptr;
   }
 
+#ifndef RELEASE_OR_BETA
+  virtual mozilla::PerformanceCounter* GetPerformanceCounter(nsIRunnable* aEvent);
+#endif
+
 private:
   void DoMainThreadSpecificProcessing(bool aReallyWait);
 
@@ -178,7 +183,13 @@ protected:
   bool mCanInvokeJS;
 
 #ifndef RELEASE_OR_BETA
+  bool GetSchedulerLoggingEnabled();
   mozilla::TimeStamp mNextIdleDeadline;
+  // Used to track which event is being executed by ProcessNextEvent
+  nsCOMPtr<nsIRunnable> mCurrentEvent;
+  mozilla::TimeStamp mCurrentEventStart;
+  uint32_t mCurrentEventLoopDepth;
+  RefPtr<mozilla::PerformanceCounter> mCurrentPerformanceCounter;
 #endif
 };