Bug 1437438 - Add a performance counter to track scheduler activity - r=farre,froydnj
authorTarek Ziadé <tarek@mozilla.com>
Tue, 06 Mar 2018 10:19:19 +0100
changeset 464185 552d61cb273abe05e86c9d64a7a0077ed1046856
parent 464184 7d509bb8a35d278c15597bff0a0e7855479987e3
child 464186 edc1455e7082f769a2c358a0b15c8950629dc4f3
push id1728
push userjlund@mozilla.com
push dateMon, 18 Jun 2018 21:12:27 +0000
treeherdermozilla-release@c296fde26f5f [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersfarre, froydnj
bugs1437438
milestone61.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 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
dom/base/DOMPrefsInternal.h
dom/base/DocGroup.cpp
dom/base/DocGroup.h
dom/ipc/ContentPrefs.cpp
dom/workers/WorkerPrivate.cpp
dom/workers/WorkerPrivate.h
dom/workers/WorkerThread.cpp
dom/workers/WorkerThread.h
modules/libpref/init/all.js
xpcom/tests/gtest/TestThreadMetrics.cpp
xpcom/tests/gtest/moz.build
xpcom/threads/PerformanceCounter.cpp
xpcom/threads/PerformanceCounter.h
xpcom/threads/moz.build
xpcom/threads/nsThread.cpp
xpcom/threads/nsThread.h
--- a/dom/base/DOMPrefsInternal.h
+++ b/dom/base/DOMPrefsInternal.h
@@ -8,26 +8,27 @@
 // main-thread in DOM.
 // The format is as follows:
 //
 //   DOM_PREF(FooBar, "foo.bar")
 //
 //   * 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);
 //     This is allows the use of DOMPrefs in WebIDL files.
 
 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_PREF(ServiceWorkersEnabled, "dom.serviceWorkers.enabled")
 DOM_PREF(ServiceWorkersTestingEnabled, "dom.serviceWorkers.testing.enabled")
 DOM_PREF(StorageManagerEnabled, "dom.storageManager.enabled")
 DOM_PREF(PromiseRejectionEventsEnabled, "dom.promise_rejection_events.enabled")
 DOM_PREF(PushEnabled, "dom.push.enabled")
--- a/dom/base/DocGroup.cpp
+++ b/dom/base/DocGroup.cpp
@@ -40,16 +40,19 @@ DocGroup::RemoveDocument(nsIDocument* aD
   MOZ_ASSERT(mDocuments.Contains(aDocument));
   mDocuments.RemoveElement(aDocument);
 }
 
 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()
 {
   MOZ_ASSERT(mDocuments.IsEmpty());
   if (!NS_IsMainThread()) {
     nsIEventTarget* target = EventTargetFor(TaskCategory::Other);
     NS_ProxyRelease("DocGroup::mReactionsStack", target, mReactionsStack.forget());
@@ -57,16 +60,19 @@ DocGroup::~DocGroup()
 
   mTabGroup->mDocGroups.RemoveEntry(mKey);
 }
 
 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);
 }
 
 nsISerialEventTarget*
 DocGroup::EventTargetFor(TaskCategory aCategory) const
 {
   return mTabGroup->EventTargetFor(aCategory);
 }
--- a/dom/base/DocGroup.h
+++ b/dom/base/DocGroup.h
@@ -11,16 +11,18 @@
 #include "nsIPrincipal.h"
 #include "nsTHashtable.h"
 #include "nsString.h"
 
 #include "mozilla/dom/TabGroup.h"
 #include "mozilla/RefPtr.h"
 #include "mozilla/dom/CustomElementRegistry.h"
 #include "mozilla/dom/HTMLSlotElement.h"
+#include "mozilla/PerformanceCounter.h"
+
 
 namespace mozilla {
 class AbstractThread;
 namespace dom {
 
 // Two browsing contexts are considered "related" if they are reachable from one
 // another through window.opener, window.parent, or window.frames. This is the
 // spec concept of a "unit of related browsing contexts"
@@ -49,16 +51,22 @@ public:
   // |aString| may still be set to an empty string.
   static MOZ_MUST_USE nsresult
   GetKey(nsIPrincipal* aPrincipal, nsACString& aString);
 
   bool MatchesKey(const nsACString& aKey)
   {
     return aKey == mKey;
   }
+#ifndef RELEASE_OR_BETA
+  PerformanceCounter* GetPerformanceCounter()
+  {
+    return mPerformanceCounter;
+  }
+#endif
   TabGroup* GetTabGroup()
   {
     return mTabGroup;
   }
   mozilla::dom::CustomElementReactionsStack* CustomElementReactionsStack()
   {
     MOZ_ASSERT(NS_IsMainThread());
     if (!mReactionsStack) {
@@ -121,14 +129,17 @@ private:
   DocGroup(TabGroup* aTabGroup, const nsACString& aKey);
   ~DocGroup();
 
   nsCString mKey;
   RefPtr<TabGroup> mTabGroup;
   nsTArray<nsIDocument*> mDocuments;
   RefPtr<mozilla::dom::CustomElementReactionsStack> mReactionsStack;
   nsTArray<RefPtr<HTMLSlotElement>> mSignalSlotList;
+#ifndef RELEASE_OR_BETA
+  RefPtr<mozilla::PerformanceCounter> mPerformanceCounter;
+#endif
 };
 
 } // namespace dom
 } // namespace mozilla
 
 #endif // defined(DocGroup_h)
--- a/dom/ipc/ContentPrefs.cpp
+++ b/dom/ipc/ContentPrefs.cpp
@@ -67,16 +67,17 @@ const char* mozilla::dom::ContentPrefs::
   "dom.ipc.processPriorityManager.backgroundGracePeriodMS",
   "dom.ipc.processPriorityManager.backgroundPerceivableGracePeriodMS",
   "dom.ipc.useNativeEventProcessing.content",
   "dom.max_chrome_script_run_time",
   "dom.max_ext_content_script_run_time",
   "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.script_loader.bytecode_cache.enabled",
   "dom.script_loader.bytecode_cache.strategy",
   "dom.storage.testing",
   "dom.url.encode_decode_hash",
   "dom.url.getters_decode_hash",
--- a/dom/workers/WorkerPrivate.cpp
+++ b/dom/workers/WorkerPrivate.cpp
@@ -83,16 +83,19 @@ WorkerLog()
 }
 
 mozilla::LogModule*
 TimeoutsLog()
 {
   return sWorkerTimeoutsLog;
 }
 
+#ifdef LOG
+#undef LOG
+#endif
 #define LOG(log, _args) MOZ_LOG(log, LogLevel::Debug, _args);
 
 namespace mozilla {
 
 using namespace ipc;
 
 namespace dom {
 
@@ -2611,16 +2614,19 @@ WorkerPrivate::WorkerPrivate(WorkerPriva
   , mFetchHandlerWasAdded(false)
   , mOnLine(false)
   , mMainThreadObjectsForgotten(false)
   , mIsChromeWorker(aIsChromeWorker)
   , mParentFrozen(false)
   , mIsSecureContext(false)
   , mDebuggerRegistered(false)
   , mIsInAutomation(false)
+#ifndef RELEASE_OR_BETA
+  , mPerformanceCounter(nullptr)
+#endif
 {
   MOZ_ASSERT_IF(!IsDedicatedWorker(), NS_IsMainThread());
   mLoadInfo.StealFrom(aLoadInfo);
 
   if (aParent) {
     aParent->AssertIsOnWorkerThread();
 
     // Note that this copies our parent's secure context state into mJSSettings.
@@ -5234,16 +5240,30 @@ WorkerPrivate::DumpCrashInformation(nsAC
   nsTObserverArray<WorkerHolder*>::ForwardIterator iter(mHolders);
   while (iter.HasMore()) {
     WorkerHolder* holder = iter.GetNext();
     aString.Append("|");
     aString.Append(holder->Name());
   }
 }
 
+#ifndef RELEASE_OR_BETA
+PerformanceCounter*
+WorkerPrivate::GetPerformanceCounter()
+{
+  AssertIsOnWorkerThread();
+
+  if (!mPerformanceCounter) {
+    mPerformanceCounter = new PerformanceCounter(NS_ConvertUTF16toUTF8(mWorkerName));
+  }
+
+  return mPerformanceCounter;
+}
+#endif
+
 PerformanceStorage*
 WorkerPrivate::GetPerformanceStorage()
 {
   AssertIsOnMainThread();
 
   if (!mPerformanceStorage) {
     mPerformanceStorage = PerformanceStorageWorker::Create(this);
   }
--- a/dom/workers/WorkerPrivate.h
+++ b/dom/workers/WorkerPrivate.h
@@ -14,16 +14,17 @@
 #include "nsIEventTarget.h"
 #include "nsTObserverArray.h"
 
 #include "mozilla/dom/Worker.h"
 #include "mozilla/dom/WorkerHolder.h"
 #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;
 
 namespace mozilla {
 namespace dom {
 
 // If you change this, the corresponding list in nsIWorkerDebugger.idl needs
@@ -568,16 +569,21 @@ public:
   Control(const ServiceWorkerDescriptor& aServiceWorker);
 
   void
   ExecutionReady();
 
   PerformanceStorage*
   GetPerformanceStorage();
 
+#ifndef RELEASE_OR_BETA
+  PerformanceCounter*
+  GetPerformanceCounter();
+#endif
+
   bool
   IsAcceptingEvents()
   {
     AssertIsOnParentThread();
 
     MutexAutoLock lock(mMutex);
     return mParentStatus < Terminating;
   }
@@ -1484,16 +1490,20 @@ private:
   // use our global object's secure state there.
   bool mIsSecureContext;
 
   bool mDebuggerRegistered;
 
   // 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
 {
   WorkerPrivate* mWorkerPrivate;
   nsCOMPtr<nsIEventTarget> mTarget;
   uint32_t mIndex;
 
--- a/dom/workers/WorkerThread.cpp
+++ b/dom/workers/WorkerThread.cpp
@@ -5,16 +5,17 @@
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #include "WorkerThread.h"
 
 #include "mozilla/Assertions.h"
 #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"
 
 #ifdef DEBUG
 #include "nsThreadManager.h"
 #endif
 
@@ -222,16 +223,25 @@ WorkerThread::Dispatch(already_AddRefed<
 
   // Workers only support asynchronous dispatch.
   if (NS_WARN_IF(aFlags != NS_DISPATCH_NORMAL)) {
     return NS_ERROR_UNEXPECTED;
   }
 
   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);
 
     {
       MutexAutoLock lock(mLock);
 
       // Only enforce cancelable runnables after we've started the worker loop.
@@ -309,16 +319,27 @@ WorkerThread::DelayedDispatch(already_Ad
 uint32_t
 WorkerThread::RecursionDepth(const WorkerThreadFriendKey& /* aKey */) const
 {
   MOZ_ASSERT(PR_GetCurrentThread() == mThread);
 
   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
 WorkerThread::Observer::OnDispatchedEvent()
 {
   MOZ_CRASH("OnDispatchedEvent() should never be called!");
 }
 
--- a/dom/workers/WorkerThread.h
+++ b/dom/workers/WorkerThread.h
@@ -76,16 +76,21 @@ public:
 
   nsresult
   DispatchAnyThread(const WorkerThreadFriendKey& aKey,
            already_AddRefed<WorkerRunnable> aWorkerRunnable);
 
   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:
   WorkerThread();
   ~WorkerThread();
 
   // This should only be called by consumers that have an
   // nsIEventTarget/nsIThread pointer.
--- a/modules/libpref/init/all.js
+++ b/modules/libpref/init/all.js
@@ -191,16 +191,19 @@ pref("dom.enable_resource_timing", true)
 pref("dom.enable_performance_navigation_timing", true);
 
 // Enable printing performance marks/measures to log
 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);
 
 // Enable exposing timeToNonBlankPaint
 pref("dom.performance.time_to_non_blank_paint.enabled", false);
 
 // Enable Performance Observer API
 pref("dom.enable_performance_observer", true);
new file mode 100644
--- /dev/null
+++ b/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);
+}
--- a/xpcom/tests/gtest/moz.build
+++ b/xpcom/tests/gtest/moz.build
@@ -46,16 +46,17 @@ UNIFIED_SOURCES += [
     'TestStrings.cpp',
     'TestStringStream.cpp',
     'TestSynchronization.cpp',
     'TestTArray.cpp',
     'TestTArray2.cpp',
     'TestTaskQueue.cpp',
     'TestTextFormatter.cpp',
     'TestThreadManager.cpp',
+    'TestThreadMetrics.cpp',
     'TestThreadPool.cpp',
     'TestThreadPoolListener.cpp',
     'TestThreads.cpp',
     'TestThreadUtils.cpp',
     'TestTimers.cpp',
     'TestTimeStamp.cpp',
     'TestTokenizer.cpp',
     'TestUTF.cpp',
new file mode 100644
--- /dev/null
+++ b/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;
+}
new file mode 100644
--- /dev/null
+++ b/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
--- a/xpcom/threads/moz.build
+++ b/xpcom/threads/moz.build
@@ -47,16 +47,17 @@ EXPORTS.mozilla += [
     'HangAnnotations.h',
     'HangMonitor.h',
     'IdleTaskRunner.h',
     'LazyIdleThread.h',
     'MainThreadIdlePeriod.h',
     'Monitor.h',
     'MozPromise.h',
     'Mutex.h',
+    'PerformanceCounter.h',
     'Queue.h',
     'RecursiveMutex.h',
     'ReentrantMonitor.h',
     'RWLock.h',
     'Scheduler.h',
     'SchedulerGroup.h',
     'SharedThreadPool.h',
     'StateMirroring.h',
@@ -92,16 +93,17 @@ UNIFIED_SOURCES += [
     'nsMemoryPressure.cpp',
     'nsProcessCommon.cpp',
     'nsProxyRelease.cpp',
     'nsThread.cpp',
     'nsThreadManager.cpp',
     'nsThreadPool.cpp',
     'nsThreadUtils.cpp',
     'nsTimerImpl.cpp',
+    'PerformanceCounter.cpp',
     'PrioritizedEventQueue.cpp',
     'RecursiveMutex.cpp',
     'RWLock.cpp',
     'Scheduler.cpp',
     'SchedulerGroup.cpp',
     'SharedThreadPool.cpp',
     'SynchronizedEventQueue.cpp',
     'SystemGroup.cpp',
--- a/xpcom/threads/nsThread.cpp
+++ b/xpcom/threads/nsThread.cpp
@@ -23,16 +23,17 @@
 #include "pratom.h"
 #include "mozilla/CycleCollectedJSContext.h"
 #include "mozilla/Logging.h"
 #include "nsIObserverService.h"
 #include "mozilla/HangMonitor.h"
 #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"
 #include "mozilla/SystemGroup.h"
 #include "nsXPCOMPrivate.h"
 #include "mozilla/ChaosMode.h"
 #include "mozilla/Telemetry.h"
 #include "mozilla/TimeStamp.h"
@@ -41,16 +42,17 @@
 #include "nsICrashReporter.h"
 #include "nsThreadSyncDispatch.h"
 #include "nsServiceManagerUtils.h"
 #include "GeckoProfiler.h"
 #include "InputEventStatistics.h"
 #include "ThreadEventTarget.h"
 
 #include "mozilla/dom/ContentChild.h"
+#include "mozilla/dom/DOMPrefs.h"
 
 #ifdef XP_LINUX
 #include <sys/time.h>
 #include <sys/resource.h>
 #include <sched.h>
 #endif
 
 #define HAVE_UALARM _BSD_SOURCE || (_XOPEN_SOURCE >= 500 ||                 \
@@ -553,16 +555,22 @@ nsThread::nsThread(NotNull<SynchronizedE
   , mThread(nullptr)
   , mNestedEventLoopDepth(0)
   , mStackSize(aStackSize)
   , mShutdownContext(nullptr)
   , mShutdownRequired(false)
   , mIsMainThread(aMainThread)
   , mLastUnlabeledRunnable(TimeStamp::Now())
   , mCanInvokeJS(false)
+#ifndef RELEASE_OR_BETA
+  , mCurrentEvent(nullptr)
+  , mCurrentEventStart(TimeStamp::Now())
+  , mCurrentEventLoopDepth(-1)
+  , mCurrentPerformanceCounter(nullptr)
+#endif
 {
 }
 
 nsThread::~nsThread()
 {
   NS_ASSERTION(mRequestedShutdownContexts.IsEmpty(),
                "shouldn't be waiting on other threads to shutdown");
 #ifdef DEBUG
@@ -573,16 +581,26 @@ nsThread::~nsThread()
   // requesting shutdown on another, which can be helpful for diagnosing
   // the leak.
   for (size_t i = 0; i < mRequestedShutdownContexts.Length(); ++i) {
     Unused << mRequestedShutdownContexts[i].forget();
   }
 #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)
 {
   // spawn thread and wait until it is fully setup
   RefPtr<nsThreadStartupEvent> startup = new nsThreadStartupEvent();
 
   NS_ADDREF_THIS();
 
@@ -902,16 +920,30 @@ GetLabeledRunnableName(nsIRunnable* aEve
   }
 
   if (!labeled && aPriority > EventPriority::Input) {
     aName.AppendLiteral("(unlabeled)");
   }
 
   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
 nsThread::ProcessNextEvent(bool aMayWait, bool* aResult)
 {
   LOG(("THRD(%p) ProcessNextEvent [%u %u]\n", this, aMayWait,
        mNestedEventLoopDepth));
 
@@ -975,16 +1007,26 @@ nsThread::ProcessNextEvent(bool aMayWait
     if (event) {
       LOG(("THRD(%p) running [%p]\n", this, event.get()));
 
       if (MAIN_THREAD == mIsMainThread) {
         HangMonitor::NotifyActivity();
       }
 
 #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;
 
       nsAutoCString name;
       if ((MAIN_THREAD == mIsMainThread) || mNextIdleDeadline) {
         bool labeled = GetLabeledRunnableName(event, name, priority);
 
         if (MAIN_THREAD == mIsMainThread) {
@@ -1032,17 +1074,52 @@ nsThread::ProcessNextEvent(bool aMayWait
         memcpy(sMainThreadRunnableName.begin(), name.BeginReading(), length);
         sMainThreadRunnableName[length] = '\0';
       }
 #endif
       Maybe<AutoTimeDurationHelper> timeDurationHelper;
       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");
       rv = NS_ERROR_UNEXPECTED;
     }
   }
 
   NOTIFY_EVENT_OBSERVERS(EventQueue()->EventObservers(), AfterProcessNextEvent, (this, *aResult));
--- a/xpcom/threads/nsThread.h
+++ b/xpcom/threads/nsThread.h
@@ -17,16 +17,17 @@
 #include "mozilla/Attributes.h"
 #include "mozilla/SynchronizedEventQueue.h"
 #include "mozilla/NotNull.h"
 #include "mozilla/TimeStamp.h"
 #include "nsAutoPtr.h"
 #include "mozilla/AlreadyAddRefed.h"
 #include "mozilla/UniquePtr.h"
 #include "mozilla/Array.h"
+#include "mozilla/dom/DocGroup.h"
 
 namespace mozilla {
 class CycleCollectedJSContext;
 class ThreadEventTarget;
 }
 
 using mozilla::NotNull;
 
@@ -124,16 +125,20 @@ public:
 
   mozilla::SynchronizedEventQueue* EventQueue() { return mEvents.get(); }
 
   bool ShuttingDown()
   {
     return mShutdownContext != nullptr;
   }
 
+#ifndef RELEASE_OR_BETA
+  virtual mozilla::PerformanceCounter* GetPerformanceCounter(nsIRunnable* aEvent);
+#endif
+
 private:
   void DoMainThreadSpecificProcessing(bool aReallyWait);
 
 protected:
   friend class nsThreadShutdownEvent;
 
   virtual ~nsThread();
 
@@ -173,17 +178,23 @@ protected:
   // 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;
 
 #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
 };
 
 #if defined(XP_UNIX) && !defined(ANDROID) && !defined(DEBUG) && HAVE_UALARM \
   && defined(_GNU_SOURCE)
 # define MOZ_CANARY
 
 extern int sCanaryOutputFD;