Bug 1437438 - Add a performance counter to track scheduler activity - r?farre r?froydnj draft
authorTarek Ziadé <tarek@mozilla.com>
Tue, 06 Mar 2018 10:19:19 +0100
changeset 767092 e54a9d6038435c5fdee7bc2ff0e18cebf217353e
parent 763042 69f9ae4f6e8943d24569a9e4380f6df869f56b73
push id102521
push usertziade@mozilla.com
push dateTue, 13 Mar 2018 23:11:16 +0000
reviewersfarre, froydnj
bugs1437438
milestone60.0a1
Bug 1437438 - Add a performance counter to track scheduler activity - r?farre r?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 {
 
@@ -2613,16 +2616,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.
@@ -5240,16 +5246,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;