Bug 1437438 - Add counters in DocGroup to track its activity - r?farre r?froydnj draft
authorTarek Ziadé <tarek@mozilla.com>
Mon, 12 Feb 2018 09:22:16 +0100
changeset 754804 ae1c3ed8217678b79f512f31e43ff9c19b3e13b7
parent 753522 a8e153c55eeee93a11e87d325fb20c644421036f
push id99005
push usertziade@mozilla.com
push dateWed, 14 Feb 2018 10:31:39 +0000
reviewersfarre, froydnj
bugs1437438
milestone60.0a1
Bug 1437438 - Add counters in DocGroup to track its activity - r?farre r?froydnj Adds 2 counters in the DocGroup class : - an array that counts how many times a runnable is dispatched - a long that counts how much time is spent in all related runnables MozReview-Commit-ID: 51DLj6ORD2O
dom/base/DOMPrefsInternal.h
dom/base/DocGroup.cpp
dom/base/DocGroup.h
modules/libpref/init/all.js
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,17 @@ 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.
+  ResetMetrics();
 }
 
 DocGroup::~DocGroup()
 {
   MOZ_ASSERT(mDocuments.IsEmpty());
   if (!NS_IsMainThread()) {
     nsIEventTarget* target = EventTargetFor(TaskCategory::Other);
     NS_ProxyRelease("DocGroup::mReactionsStack", target, mReactionsStack.forget());
@@ -57,19 +58,26 @@ DocGroup::~DocGroup()
 
   mTabGroup->mDocGroups.RemoveEntry(mKey);
 }
 
 nsresult
 DocGroup::Dispatch(TaskCategory aCategory,
                    already_AddRefed<nsIRunnable>&& aRunnable)
 {
+  mMetrics[(size_t)aCategory] += 1;
   return mTabGroup->DispatchWithDocGroup(aCategory, Move(aRunnable), this);
 }
 
+void
+DocGroup::IncrementExecutionDuration(mozilla::TimeDuration aDuration)
+{
+  mExecutionDuration = mExecutionDuration + (uint64_t)aDuration.ToMicroseconds();
+}
+
 nsISerialEventTarget*
 DocGroup::EventTargetFor(TaskCategory aCategory) const
 {
   return mTabGroup->EventTargetFor(aCategory);
 }
 
 AbstractThread*
 DocGroup::AbstractMainThreadFor(TaskCategory aCategory)
--- a/dom/base/DocGroup.h
+++ b/dom/base/DocGroup.h
@@ -31,16 +31,18 @@ namespace dom {
 //
 // A TabGroup is a set of browsing contexts which are all "related". Within a
 // TabGroup, browsing contexts are broken into "similar-origin" DocGroups. In
 // more detail, a DocGroup is actually a collection of documents, and a
 // TabGroup is a collection of DocGroups. A TabGroup typically will contain
 // (through its DocGroups) the documents from one or more tabs related by
 // window.opener. A DocGroup is a member of exactly one TabGroup.
 
+typedef mozilla::Array<Atomic<uint32_t>, (size_t)TaskCategory::Count> DocGroupMetrics;
+
 class DocGroup final
 {
 public:
   typedef nsTArray<nsIDocument*>::iterator Iterator;
   friend class TabGroup;
 
   NS_INLINE_DECL_THREADSAFE_REFCOUNTING(DocGroup)
 
@@ -49,16 +51,32 @@ 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;
   }
+  const DocGroupMetrics& GetMetrics()
+  {
+    return mMetrics;
+  }
+  void ResetMetrics()
+  {
+    for (auto& cnt : mMetrics) {
+      cnt = 0;
+    }
+    mExecutionDuration = 0;
+  }
+  void IncrementExecutionDuration(mozilla::TimeDuration aDuration);
+  uint64_t GetExecutionDuration()
+  {
+    return mExecutionDuration;
+  }
   TabGroup* GetTabGroup()
   {
     return mTabGroup;
   }
   mozilla::dom::CustomElementReactionsStack* CustomElementReactionsStack()
   {
     MOZ_ASSERT(NS_IsMainThread());
     if (!mReactionsStack) {
@@ -121,14 +139,16 @@ 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;
+  uint64_t mExecutionDuration;
+  DocGroupMetrics mMetrics;
 };
 
 } // namespace dom
 } // namespace mozilla
 
 #endif // defined(DocGroup_h)
--- a/modules/libpref/init/all.js
+++ b/modules/libpref/init/all.js
@@ -179,16 +179,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);
--- a/xpcom/threads/moz.build
+++ b/xpcom/threads/moz.build
@@ -104,17 +104,17 @@ UNIFIED_SOURCES += [
     'SchedulerGroup.cpp',
     'SharedThreadPool.cpp',
     'SynchronizedEventQueue.cpp',
     'SystemGroup.cpp',
     'TaskQueue.cpp',
     'ThreadEventQueue.cpp',
     'ThreadEventTarget.cpp',
     'ThrottledEventQueue.cpp',
-    'TimerThread.cpp',
+    'TimerThread.cpp'
 ]
 
 LOCAL_INCLUDES += [
     '../build',
     '/caps',
     '/tools/profiler',
 ]
 
--- a/xpcom/threads/nsThread.cpp
+++ b/xpcom/threads/nsThread.cpp
@@ -23,34 +23,37 @@
 #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"
 #include "mozilla/Unused.h"
 #include "mozilla/dom/ScriptSettings.h"
+#include "mozilla/dom/DOMPrefs.h"
 #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/DocGroup.h"
 
 #ifdef XP_LINUX
 #include <sys/time.h>
 #include <sys/resource.h>
 #include <sched.h>
 #endif
 
 #define HAVE_UALARM _BSD_SOURCE || (_XOPEN_SOURCE >= 500 ||                 \
@@ -371,16 +374,17 @@ namespace {
 
 struct ThreadInitData {
   nsThread* thread;
   const nsACString& name;
 };
 
 }
 
+
 /*static*/ void
 nsThread::ThreadFunc(void* aArg)
 {
   using mozilla::ipc::BackgroundChild;
 
   ThreadInitData* initData = static_cast<ThreadInitData*>(aArg);
   nsThread* self = initData->thread;  // strong reference
 
@@ -553,16 +557,21 @@ 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)
+#endif
 {
 }
 
 nsThread::~nsThread()
 {
   NS_ASSERTION(mRequestedShutdownContexts.IsEmpty(),
                "shouldn't be waiting on other threads to shutdown");
 #ifdef DEBUG
@@ -631,17 +640,16 @@ nsThread::DispatchFromScript(nsIRunnable
   nsCOMPtr<nsIRunnable> event(aEvent);
   return mEventTarget->Dispatch(event.forget(), aFlags);
 }
 
 NS_IMETHODIMP
 nsThread::Dispatch(already_AddRefed<nsIRunnable> aEvent, uint32_t aFlags)
 {
   LOG(("THRD(%p) Dispatch [%p %x]\n", this, /* XXX aEvent */nullptr, aFlags));
-
   return mEventTarget->Dispatch(Move(aEvent), aFlags);
 }
 
 NS_IMETHODIMP
 nsThread::DelayedDispatch(already_AddRefed<nsIRunnable> aEvent, uint32_t aDelayMs)
 {
   return mEventTarget->DelayedDispatch(Move(aEvent), aDelayMs);
 }
@@ -904,16 +912,28 @@ GetLabeledRunnableName(nsIRunnable* aEve
   if (!labeled && aPriority > EventPriority::Input) {
     aName.AppendLiteral("(unlabeled)");
   }
 
   return labeled;
 }
 #endif
 
+void
+nsThread::RecordExecutionTimeForGroup(nsIRunnable* aEvent, mozilla::TimeDuration aDuration)
+{
+  RefPtr<SchedulerGroup::Runnable> docRunnable = do_QueryObject(aEvent);
+  if (docRunnable) {
+    mozilla::dom::DocGroup* group = docRunnable->DocGroup();
+    if (group) {
+      group->IncrementExecutionDuration(aDuration);
+    }
+  }
+}
+
 NS_IMETHODIMP
 nsThread::ProcessNextEvent(bool aMayWait, bool* aResult)
 {
   LOG(("THRD(%p) ProcessNextEvent [%u %u]\n", this, aMayWait,
        mNestedEventLoopDepth));
 
   if (NS_WARN_IF(PR_GetCurrentThread() != mThread)) {
     return NS_ERROR_NOT_SAME_THREAD;
@@ -969,22 +989,34 @@ nsThread::ProcessNextEvent(bool aMayWait
     if (activation.isSome()) {
       activation.ref().SetEvent(event, priority);
     }
 
     *aResult = (event.get() != nullptr);
 
     if (event) {
       LOG(("THRD(%p) running [%p]\n", this, event.get()));
-
       if (MAIN_THREAD == mIsMainThread) {
         HangMonitor::NotifyActivity();
       }
 
 #ifndef RELEASE_OR_BETA
+
+      // The event starts to run, storing the timestamp
+      if (mozilla::dom::DOMPrefs::SchedulerLoggingEnabled()
+          && MAIN_THREAD == mIsMainThread) {
+        if (mNestedEventLoopDepth > mCurrentEventLoopDepth ) {
+          // this is a recursive call, we want to send the time of
+          // the parent even and then reset the timer
+          mozilla::TimeDuration duration = TimeStamp::Now() - mCurrentEventStart;
+          LOG(("[%d] Recording parent execution time for %p: %f", mNestedEventLoopDepth, mCurrentEvent.get(), duration.ToMilliseconds()));
+          RecordExecutionTimeForGroup(mCurrentEvent, duration);
+        }
+     }
+
       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 +1064,38 @@ 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
+      if (mozilla::dom::DOMPrefs::SchedulerLoggingEnabled()
+          && MAIN_THREAD == mIsMainThread) {
+        LOG(("[%d] Starting to record for %p", mNestedEventLoopDepth, event.get()));
+        mCurrentEventStart = mozilla::TimeStamp::Now();
+        mCurrentEvent = event;
+        mCurrentEventLoopDepth = mNestedEventLoopDepth;
+      }
+#endif
       event->Run();
+
+#ifndef RELEASE_OR_BETA
+      // End of execution , we can send the duration for the group
+      if (mozilla::dom::DOMPrefs::SchedulerLoggingEnabled()
+          && MAIN_THREAD == mIsMainThread) {
+        mozilla::TimeDuration duration = TimeStamp::Now() - mCurrentEventStart;
+        LOG(("[%d] Recording execution time for %p: %f", mNestedEventLoopDepth, event.get(), duration.ToMilliseconds()));
+        RecordExecutionTimeForGroup(event, duration);
+    }
+#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
@@ -8,16 +8,17 @@
 #define nsThread_h__
 
 #include "mozilla/Mutex.h"
 #include "nsIIdlePeriod.h"
 #include "nsIThreadInternal.h"
 #include "nsISupportsPriority.h"
 #include "nsThreadUtils.h"
 #include "nsString.h"
+#include "nsQueryObject.h"
 #include "nsTObserverArray.h"
 #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"
@@ -126,17 +127,17 @@ public:
 
   bool ShuttingDown()
   {
     return mShutdownContext != nullptr;
   }
 
 private:
   void DoMainThreadSpecificProcessing(bool aReallyWait);
-
+  void RecordExecutionTimeForGroup(nsIRunnable* aEvent, mozilla::TimeDuration aDuration);
 protected:
   friend class nsThreadShutdownEvent;
 
   virtual ~nsThread();
 
   static void ThreadFunc(void* aArg);
 
   // Helper
@@ -174,16 +175,20 @@ protected:
   // SchedulerGroup).
   mozilla::TimeStamp mLastUnlabeledRunnable;
 
   // Set to true if this thread creates a JSRuntime.
   bool mCanInvokeJS;
 
 #ifndef RELEASE_OR_BETA
   mozilla::TimeStamp mNextIdleDeadline;
+  // Used to track which event is being executed by ProcessNextEvent
+  nsCOMPtr<nsIRunnable> mCurrentEvent;
+  mozilla::TimeStamp mCurrentEventStart;
+  uint32_t mCurrentEventLoopDepth;
 #endif
 };
 
 #if defined(XP_UNIX) && !defined(ANDROID) && !defined(DEBUG) && HAVE_UALARM \
   && defined(_GNU_SOURCE)
 # define MOZ_CANARY
 
 extern int sCanaryOutputFD;