From 86edd52973e2448026a08c78c9be0b92fa2fc0c5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tarek=20Ziad=C3=A9?= Date: Tue, 6 Mar 2018 10:19:19 +0100 Subject: [PATCH] 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 | 3 +- dom/base/DocGroup.cpp | 6 + dom/base/DocGroup.h | 11 ++ dom/ipc/ContentPrefs.cpp | 1 + dom/workers/WorkerPrivate.cpp | 20 +++ dom/workers/WorkerPrivate.h | 10 ++ dom/workers/WorkerThread.cpp | 21 +++ dom/workers/WorkerThread.h | 5 + modules/libpref/init/all.js | 3 + xpcom/tests/gtest/TestThreadMetrics.cpp | 200 ++++++++++++++++++++++++ xpcom/tests/gtest/moz.build | 1 + xpcom/threads/PerformanceCounter.cpp | 75 +++++++++ xpcom/threads/PerformanceCounter.h | 128 +++++++++++++++ xpcom/threads/moz.build | 2 + xpcom/threads/nsThread.cpp | 77 +++++++++ xpcom/threads/nsThread.h | 11 ++ 16 files changed, 573 insertions(+), 1 deletion(-) create mode 100644 xpcom/tests/gtest/TestThreadMetrics.cpp create mode 100644 xpcom/threads/PerformanceCounter.cpp create mode 100644 xpcom/threads/PerformanceCounter.h diff --git a/dom/base/DOMPrefsInternal.h b/dom/base/DOMPrefsInternal.h index c539e7f73c7a..81a700167e7e 100644 --- a/dom/base/DOMPrefsInternal.h +++ b/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") diff --git a/dom/base/DocGroup.cpp b/dom/base/DocGroup.cpp index c6acf248ffca..18b6d4e73b61 100644 --- a/dom/base/DocGroup.cpp +++ b/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&& aRunnable) { +#ifndef RELEASE_OR_BETA + mPerformanceCounter->IncrementDispatchCounter(DispatchCategory(aCategory)); +#endif return mTabGroup->DispatchWithDocGroup(aCategory, Move(aRunnable), this); } diff --git a/dom/base/DocGroup.h b/dom/base/DocGroup.h index 5710d6752f7a..10135e233ae6 100644 --- a/dom/base/DocGroup.h +++ b/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 mDocuments; RefPtr mReactionsStack; nsTArray> mSignalSlotList; +#ifndef RELEASE_OR_BETA + RefPtr mPerformanceCounter; +#endif }; } // namespace dom diff --git a/dom/ipc/ContentPrefs.cpp b/dom/ipc/ContentPrefs.cpp index f5a2ad878698..b71833a37f69 100644 --- a/dom/ipc/ContentPrefs.cpp +++ b/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", diff --git a/dom/workers/WorkerPrivate.cpp b/dom/workers/WorkerPrivate.cpp index 5b2afd5e0116..e87c1fbd1a2b 100644 --- a/dom/workers/WorkerPrivate.cpp +++ b/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() { diff --git a/dom/workers/WorkerPrivate.h b/dom/workers/WorkerPrivate.h index d94bb37ca6db..99029a6768e0 100644 --- a/dom/workers/WorkerPrivate.h +++ b/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 mPerformanceCounter; +#endif }; class AutoSyncLoopHolder diff --git a/dom/workers/WorkerThread.cpp b/dom/workers/WorkerThread.cpp index c0610dcd99ae..efc239889000 100644 --- a/dom/workers/WorkerThread.cpp +++ b/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 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 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 diff --git a/dom/workers/WorkerThread.h b/dom/workers/WorkerThread.h index cb824b57c5a7..fae7f6e98fb3 100644 --- a/dom/workers/WorkerThread.h +++ b/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: diff --git a/modules/libpref/init/all.js b/modules/libpref/init/all.js index 39103be8fdb0..8c1b0e7510b5 100644 --- a/modules/libpref/init/all.js +++ b/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); diff --git a/xpcom/tests/gtest/TestThreadMetrics.cpp b/xpcom/tests/gtest/TestThreadMetrics.cpp new file mode 100644 index 000000000000..fb7b5c222a3b --- /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 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 thread = do_GetMainThread(); + nsCOMPtr 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 doc; + RefPtr 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 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; + RefPtr mDocGroup; + RefPtr mCounter; + nsCOMPtr 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); +} diff --git a/xpcom/tests/gtest/moz.build b/xpcom/tests/gtest/moz.build index 4fb9f356a7ba..86a52d60fee3 100644 --- a/xpcom/tests/gtest/moz.build +++ b/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', diff --git a/xpcom/threads/PerformanceCounter.cpp b/xpcom/threads/PerformanceCounter.cpp new file mode 100644 index 000000000000..1cf74f141ec8 --- /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; +} diff --git a/xpcom/threads/PerformanceCounter.h b/xpcom/threads/PerformanceCounter.h new file mode 100644 index 000000000000..6403e3b737ab --- /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, (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 mExecutionDuration; + Atomic mTotalDispatchCount; + DispatchCounter mDispatchCounter; + nsCString mName; +}; + +} // namespace mozilla + +#endif // mozilla_PerformanceCounter_h diff --git a/xpcom/threads/moz.build b/xpcom/threads/moz.build index 1953c5affcd9..f7abd87fc849 100644 --- a/xpcom/threads/moz.build +++ b/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', diff --git a/xpcom/threads/nsThread.cpp b/xpcom/threads/nsThread.cpp index 826c9e99d508..5544337b2ab3 100644 --- a/xpcom/threads/nsThread.cpp +++ b/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 @@ -558,6 +560,12 @@ nsThread::nsThread(NotNull 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 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> timer; Maybe> 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 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"); diff --git a/xpcom/threads/nsThread.h b/xpcom/threads/nsThread.h index 00049a2c8e4f..4de24d24558f 100644 --- a/xpcom/threads/nsThread.h +++ b/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 mCurrentEvent; + mozilla::TimeStamp mCurrentEventStart; + uint32_t mCurrentEventLoopDepth; + RefPtr mCurrentPerformanceCounter; #endif };