Bug 1322184 - Measure time spent in content JS that causes delay in paint. r=billm, data-r=bsmedberg
authorAndreas Farre <farre@mozilla.com>
Tue, 02 May 2017 08:10:00 -0400
changeset 391881 08d888f39c153a5fd8c2aee35f4d1f609682ec92
parent 391880 41e9af8078dd30bb0dd8de901c9ad1869a6b677c
child 391882 c07319097f3b76aa6fe758a0246d2d2958eea717
push idunknown
push userunknown
push dateunknown
reviewersbillm
bugs1322184
milestone55.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 1322184 - Measure time spent in content JS that causes delay in paint. r=billm, data-r=bsmedberg MozReview-Commit-ID: Iz31CKSnDdc
dom/base/TabGroup.cpp
dom/base/TabGroup.h
ipc/glue/BackgroundChildImpl.cpp
ipc/glue/BackgroundChildImpl.h
ipc/glue/MessageChannel.cpp
ipc/glue/ProtocolUtils.h
layout/ipc/VsyncChild.cpp
toolkit/components/telemetry/Histograms.json
xpcom/threads/SchedulerGroup.cpp
xpcom/threads/SchedulerGroup.h
--- a/dom/base/TabGroup.cpp
+++ b/dom/base/TabGroup.cpp
@@ -216,17 +216,17 @@ TabGroup::FindItemWithName(const nsAStri
       }
     }
   }
 
   return NS_OK;
 }
 
 nsTArray<nsPIDOMWindowOuter*>
-TabGroup::GetTopLevelWindows()
+TabGroup::GetTopLevelWindows() const
 {
   MOZ_ASSERT(NS_IsMainThread());
   nsTArray<nsPIDOMWindowOuter*> array;
 
   for (nsPIDOMWindowOuter* outerWindow : mWindows) {
     if (outerWindow->GetDocShell() &&
         !outerWindow->GetScriptableParentOrNull()) {
       array.AppendElement(outerWindow);
@@ -258,10 +258,22 @@ TabGroup::AbstractMainThreadForImpl(Task
   // We'll just go directly to the main thread.
   if (this == sChromeTabGroup || NS_WARN_IF(mLastWindowLeft)) {
     return AbstractThread::MainThread();
   }
 
   return SchedulerGroup::AbstractMainThreadForImpl(aCategory);
 }
 
+bool
+TabGroup::IsBackground() const
+{
+  MOZ_RELEASE_ASSERT(NS_IsMainThread());
+
+  for (nsPIDOMWindowOuter* outerWindow : GetTopLevelWindows()) {
+    if (!outerWindow->IsBackground()) {
+      return false;
+    }
+  }
+  return true;
+}
 } // namespace dom
 } // namespace mozilla
--- a/dom/base/TabGroup.h
+++ b/dom/base/TabGroup.h
@@ -109,23 +109,27 @@ public:
   // It is illegal to pass in the special case-insensitive names "_blank",
   // "_self", "_parent" or "_top", as those should be handled elsewhere.
   nsresult
   FindItemWithName(const nsAString& aName,
                    nsIDocShellTreeItem* aRequestor,
                    nsIDocShellTreeItem* aOriginalRequestor,
                    nsIDocShellTreeItem** aFoundItem);
 
-  nsTArray<nsPIDOMWindowOuter*> GetTopLevelWindows();
+  nsTArray<nsPIDOMWindowOuter*> GetTopLevelWindows() const;
   const nsTArray<nsPIDOMWindowOuter*>& GetWindows() { return mWindows; }
 
   // This method is always safe to call off the main thread. The nsIEventTarget
   // can always be used off the main thread.
   nsIEventTarget* EventTargetFor(TaskCategory aCategory) const override;
 
+  // Returns true if all of the TabGroup's top-level windows are in
+  // the background.
+  bool IsBackground() const override;
+
 private:
   virtual AbstractThread*
   AbstractMainThreadForImpl(TaskCategory aCategory) override;
 
   TabGroup* AsTabGroup() override { return this; }
 
   void EnsureThrottledEventQueues();
 
--- a/ipc/glue/BackgroundChildImpl.cpp
+++ b/ipc/glue/BackgroundChildImpl.cpp
@@ -10,16 +10,17 @@
 #include "BroadcastChannelChild.h"
 #include "ServiceWorkerManagerChild.h"
 #include "FileDescriptorSetChild.h"
 #ifdef MOZ_WEBRTC
 #include "CamerasChild.h"
 #endif
 #include "mozilla/media/MediaChild.h"
 #include "mozilla/Assertions.h"
+#include "mozilla/SchedulerGroup.h"
 #include "mozilla/dom/PBlobChild.h"
 #include "mozilla/dom/PFileSystemRequestChild.h"
 #include "mozilla/dom/FileSystemTaskBase.h"
 #include "mozilla/dom/asmjscache/AsmJSCache.h"
 #include "mozilla/dom/cache/ActorUtils.h"
 #include "mozilla/dom/indexedDB/PBackgroundIDBFactoryChild.h"
 #include "mozilla/dom/indexedDB/PBackgroundIndexedDBUtilsChild.h"
 #include "mozilla/dom/ipc/BlobChild.h"
@@ -542,16 +543,28 @@ BackgroundChildImpl::AllocPGamepadTestCh
 bool
 BackgroundChildImpl::DeallocPGamepadTestChannelChild(PGamepadTestChannelChild* aActor)
 {
   MOZ_ASSERT(aActor);
   delete static_cast<dom::GamepadTestChannelChild*>(aActor);
   return true;
 }
 
+#ifdef EARLY_BETA_OR_EARLIER
+void
+BackgroundChildImpl::OnChannelReceivedMessage(const Message& aMsg)
+{
+  if (aMsg.type() == layout::PVsync::MessageType::Msg_Notify__ID) {
+    // Not really necessary to look at the message payload, it will be
+    // <0.5ms away from TimeStamp::Now()
+    SchedulerGroup::MarkVsyncReceived();
+  }
+}
+#endif
+
 } // namespace ipc
 } // namespace mozilla
 
 mozilla::ipc::IPCResult
 TestChild::Recv__delete__(const nsCString& aTestArg)
 {
   MOZ_RELEASE_ASSERT(aTestArg == mTestArg,
                      "BackgroundTest message was corrupted!");
--- a/ipc/glue/BackgroundChildImpl.h
+++ b/ipc/glue/BackgroundChildImpl.h
@@ -192,16 +192,21 @@ protected:
   virtual bool
   DeallocPGamepadEventChannelChild(PGamepadEventChannelChild* aActor) override;
 
   virtual PGamepadTestChannelChild*
   AllocPGamepadTestChannelChild() override;
 
   virtual bool
   DeallocPGamepadTestChannelChild(PGamepadTestChannelChild* aActor) override;
+
+#ifdef EARLY_BETA_OR_EARLIER
+  virtual void
+  OnChannelReceivedMessage(const Message& aMsg) override;
+#endif
 };
 
 class BackgroundChildImpl::ThreadLocal final
 {
   friend class nsAutoPtr<ThreadLocal>;
 
 public:
   nsAutoPtr<mozilla::dom::indexedDB::ThreadLocal> mIndexedDBThreadLocal;
--- a/ipc/glue/MessageChannel.cpp
+++ b/ipc/glue/MessageChannel.cpp
@@ -1083,16 +1083,18 @@ void
 MessageChannel::OnMessageReceivedFromLink(Message&& aMsg)
 {
     AssertLinkThread();
     mMonitor->AssertCurrentThreadOwns();
 
     if (MaybeInterceptSpecialIOMessage(aMsg))
         return;
 
+    mListener->OnChannelReceivedMessage(aMsg);
+
     // Regardless of the Interrupt stack, if we're awaiting a sync reply,
     // we know that it needs to be immediately handled to unblock us.
     if (aMsg.is_sync() && aMsg.is_reply()) {
         IPC_LOG("Received reply seqno=%d xid=%d", aMsg.seqno(), aMsg.transaction_id());
 
         if (aMsg.seqno() == mTimedOutMessageSeqno) {
             // Drop the message, but allow future sync messages to be sent.
             IPC_LOG("Received reply to timedout message; igoring; xid=%d", mTimedOutMessageSeqno);
--- a/ipc/glue/ProtocolUtils.h
+++ b/ipc/glue/ProtocolUtils.h
@@ -371,16 +371,17 @@ public:
     GetMessageEventTarget(const Message& aMsg);
 
     already_AddRefed<nsIEventTarget>
     GetActorEventTarget(IProtocol* aActor);
 
     virtual nsIEventTarget*
     GetActorEventTarget();
 
+    virtual void OnChannelReceivedMessage(const Message& aMsg) {}
 protected:
     // Override this method in top-level protocols to change the event target
     // for a new actor (and its sub-actors).
     virtual already_AddRefed<nsIEventTarget>
     GetConstructedEventTarget(const Message& aMsg) { return nullptr; }
 
     // Override this method in top-level protocols to change the event target
     // for specific messages.
--- a/layout/ipc/VsyncChild.cpp
+++ b/layout/ipc/VsyncChild.cpp
@@ -1,15 +1,16 @@
 /* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
 /* 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 "VsyncChild.h"
 
+#include "mozilla/SchedulerGroup.h"
 #include "mozilla/VsyncDispatcher.h"
 #include "nsThreadUtils.h"
 
 namespace mozilla {
 namespace layout {
 
 VsyncChild::VsyncChild()
   : mObservingVsync(false)
@@ -55,16 +56,18 @@ VsyncChild::ActorDestroy(ActorDestroyRea
   mObserver = nullptr;
 }
 
 mozilla::ipc::IPCResult
 VsyncChild::RecvNotify(const TimeStamp& aVsyncTimestamp)
 {
   MOZ_ASSERT(NS_IsMainThread());
   MOZ_ASSERT(!mIsShutdown);
+
+  SchedulerGroup::MarkVsyncRan();
   if (mObservingVsync && mObserver) {
     mObserver->NotifyVsync(aVsyncTimestamp);
   }
   return IPC_OK();
 }
 
 void
 VsyncChild::SetVsyncObserver(VsyncObserver* aVsyncObserver)
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -278,16 +278,63 @@
   },
   "COMPOSITE_FRAME_ROUNDTRIP_TIME" : {
     "expires_in_version": "never",
     "description": "Time from vsync to finishing a composite in milliseconds.",
     "kind": "exponential",
     "high": 1000,
     "n_buckets": 50
   },
+  "CONTENT_JS_FOREGROUND_TICK_DELAY_TOTAL_MS": {
+    "alert_emails": ["farre@mozilla.com"],
+    "expires_in_version": "61",
+    "kind": "exponential",
+    "high": 100,
+    "n_buckets": 10,
+    "bug_numbers": [1305153, 1296486],
+    "description": "Time (in ms) that a pending vsync gets delayed by a runnable associated with a TabGroup that is (partially) in the foreground. The time is measured from the vsync event's time stamp to when the runnable finishes execution."
+  },
+  "CONTENT_JS_FOREGROUND_TICK_DELAY_EVENTS_MS": {
+    "alert_emails": ["farre@mozilla.com"],
+    "expires_in_version": "61",
+    "keyed": true,
+    "kind": "exponential",
+    "high": 100,
+    "n_buckets": 10,
+    "bug_numbers": [1305153, 1296486],
+    "description": "Time (in ms) that a pending vsync gets delayed by a runnable associated with a TabGroup that is (partially) in the foreground. The time is measured from the vsync event's time stamp to when the runnable finishes execution. The histogram is keyed by the label of the runnable, indicating which type of task the runnable is performing."
+  },
+  "CONTENT_JS_BACKGROUND_TICK_DELAY_TOTAL_MS": {
+    "alert_emails": ["farre@mozilla.com"],
+    "expires_in_version": "61",
+    "kind": "exponential",
+    "high": 100,
+    "n_buckets": 10,
+    "bug_numbers": [1305153, 1296486],
+    "description": "Time (in ms) that a pending vsync gets delayed by a runnable associated with a TabGroup that is completely in the background. The time is measured from the vsync event's time stamp to when the runnable finishes execution."
+  },
+  "CONTENT_JS_BACKGROUND_TICK_DELAY_EVENTS_MS": {
+    "alert_emails": ["farre@mozilla.com"],
+    "expires_in_version": "61",
+    "keyed": true,
+    "kind": "exponential",
+    "high": 100,
+    "n_buckets": 10,
+    "bug_numbers": [1305153, 1296486],
+    "description" : "Time (in ms) that a pending vsync gets delayed by a runnable associated with a TabGroup that is completely in the background. The time is measured from the vsync event's time stamp to when the runnable finishes execution. The histogram is keyed by the label of the runnable, indicating which type of task the runnable is performing."
+  },
+  "CONTENT_JS_KNOWN_TICK_DELAY_MS": {
+    "alert_emails": ["farre@mozilla.com"],
+    "expires_in_version": "65",
+    "kind": "exponential",
+    "high": 100,
+    "n_buckets": 10,
+    "bug_numbers": [1305153, 1296486],
+    "description": "Time (in ms) that a pending vsync gets delayed by a runnable associated with a TabGroup when the vsync event's timestamp is before the starting time of the runnable. The time is measured from the vsync event's time stamp to when the runnable finishes execution."
+  },
   "COMPOSITOR_ANIMATION_DURATION" : {
     "expires_in_version": "58",
     "description": "Duration of animations running on the compositor in milliseconds",
     "kind": "exponential",
     "high": 20000,
     "n_buckets": 50,
     "alert_emails": ["kgupta@mozilla.com"],
     "bug_numbers": [1339220]
--- a/xpcom/threads/SchedulerGroup.cpp
+++ b/xpcom/threads/SchedulerGroup.cpp
@@ -3,22 +3,25 @@
 /* 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/SchedulerGroup.h"
 
 #include "jsfriendapi.h"
 #include "mozilla/AbstractThread.h"
+#include "mozilla/Atomics.h"
 #include "mozilla/Move.h"
 #include "nsINamed.h"
 #include "nsQueryObject.h"
 #include "mozilla/dom/ScriptSettings.h"
 #include "nsThreadUtils.h"
 
+#include "mozilla/Telemetry.h"
+
 using namespace mozilla;
 
 class SchedulerGroup::Runnable final : public mozilla::Runnable
 {
 public:
   Runnable(already_AddRefed<nsIRunnable>&& aRunnable,
            SchedulerGroup* aDispatcher);
 
@@ -32,18 +35,19 @@ public:
       if (named) {
         named->GetName(aName);
       }
     }
     aName.AppendASCII("(labeled)");
     return NS_OK;
   }
 
+  bool IsBackground() const { return mDispatcher->IsBackground(); }
+
   NS_DECL_NSIRUNNABLE
-
 private:
   nsCOMPtr<nsIRunnable> mRunnable;
   RefPtr<SchedulerGroup> mDispatcher;
 };
 
 /* SchedulerEventTarget */
 
 namespace {
@@ -71,16 +75,94 @@ public:
   SchedulerGroup* Dispatcher() const { return mDispatcher; }
 
 private:
   ~SchedulerEventTarget() {}
 };
 
 NS_DEFINE_STATIC_IID_ACCESSOR(SchedulerEventTarget, NS_DISPATCHEREVENTTARGET_IID)
 
+static Atomic<uint64_t> gEarliestUnprocessedVsync(0);
+
+class MOZ_RAII AutoCollectVsyncTelemetry final
+{
+public:
+  explicit AutoCollectVsyncTelemetry(SchedulerGroup::Runnable* aRunnable
+                                     MOZ_GUARD_OBJECT_NOTIFIER_PARAM)
+    : mIsBackground(aRunnable->IsBackground())
+  {
+    MOZ_GUARD_OBJECT_NOTIFIER_INIT;
+#ifdef EARLY_BETA_OR_EARLIER
+    aRunnable->GetName(mKey);
+    mStart = TimeStamp::Now();
+#endif
+  }
+  ~AutoCollectVsyncTelemetry()
+  {
+#ifdef EARLY_BETA_OR_EARLIER
+    if (Telemetry::CanRecordBase()) {
+      CollectTelemetry();
+    }
+#endif
+  }
+
+private:
+  void CollectTelemetry();
+
+  bool mIsBackground;
+  nsCString mKey;
+  TimeStamp mStart;
+  MOZ_DECL_USE_GUARD_OBJECT_NOTIFIER
+};
+
+void
+AutoCollectVsyncTelemetry::CollectTelemetry()
+{
+  TimeStamp now = TimeStamp::Now();
+
+  mozilla::Telemetry::HistogramID eventsId =
+    mIsBackground ? Telemetry::CONTENT_JS_BACKGROUND_TICK_DELAY_EVENTS_MS
+                  : Telemetry::CONTENT_JS_FOREGROUND_TICK_DELAY_EVENTS_MS;
+  mozilla::Telemetry::HistogramID totalId =
+    mIsBackground ? Telemetry::CONTENT_JS_BACKGROUND_TICK_DELAY_TOTAL_MS
+                  : Telemetry::CONTENT_JS_FOREGROUND_TICK_DELAY_TOTAL_MS;
+
+  uint64_t lastSeenVsync = gEarliestUnprocessedVsync;
+  if (!lastSeenVsync) {
+    return;
+  }
+
+  bool inconsistent = false;
+  TimeStamp creation = TimeStamp::ProcessCreation(&inconsistent);
+  if (inconsistent) {
+    return;
+  }
+
+  TimeStamp pendingVsync =
+    creation + TimeDuration::FromMicroseconds(lastSeenVsync);
+
+  if (pendingVsync > now) {
+    return;
+  }
+
+  uint32_t duration =
+    static_cast<uint32_t>((now - pendingVsync).ToMilliseconds());
+
+  Telemetry::Accumulate(eventsId, mKey, duration);
+  Telemetry::Accumulate(totalId, duration);
+
+  if (pendingVsync > mStart) {
+    return;
+  }
+
+  Telemetry::Accumulate(Telemetry::CONTENT_JS_KNOWN_TICK_DELAY_MS, duration);
+
+  return;
+}
+
 } // namespace
 
 NS_IMPL_ISUPPORTS(SchedulerEventTarget, SchedulerEventTarget, nsIEventTarget)
 
 NS_IMETHODIMP
 SchedulerEventTarget::DispatchFromScript(nsIRunnable* aRunnable, uint32_t aFlags)
 {
   return Dispatch(do_AddRef(aRunnable), aFlags);
@@ -121,16 +203,41 @@ SchedulerGroup::UnlabeledDispatch(const 
   }
   if (NS_IsMainThread()) {
     return NS_DispatchToCurrentThread(runnable.forget());
   } else {
     return NS_DispatchToMainThread(runnable.forget());
   }
 }
 
+/* static */ void
+SchedulerGroup::MarkVsyncReceived()
+{
+  if (gEarliestUnprocessedVsync) {
+    // If we've seen a vsync already, but haven't handled it, keep the
+    // older one.
+    return;
+  }
+
+  MOZ_ASSERT(!NS_IsMainThread());
+  bool inconsistent = false;
+  TimeStamp creation = TimeStamp::ProcessCreation(&inconsistent);
+  if (inconsistent) {
+    return;
+  }
+
+  gEarliestUnprocessedVsync = (TimeStamp::Now() - creation).ToMicroseconds();
+}
+
+/* static */ void
+SchedulerGroup::MarkVsyncRan()
+{
+  gEarliestUnprocessedVsync = 0;
+}
+
 SchedulerGroup* SchedulerGroup::sRunningDispatcher;
 
 SchedulerGroup::SchedulerGroup()
  : mAccessValid(false)
 {
 }
 
 nsresult
@@ -251,17 +358,22 @@ SchedulerGroup::Runnable::Runnable(alrea
 
 NS_IMETHODIMP
 SchedulerGroup::Runnable::Run()
 {
   MOZ_RELEASE_ASSERT(NS_IsMainThread());
 
   mDispatcher->SetValidatingAccess(StartValidation);
 
-  nsresult result = mRunnable->Run();
+  nsresult result;
+
+  {
+    AutoCollectVsyncTelemetry telemetry(this);
+    result = mRunnable->Run();
+  }
 
   // The runnable's destructor can have side effects, so try to execute it in
   // the scope of the TabGroup.
   mRunnable = nullptr;
 
   mDispatcher->SetValidatingAccess(EndValidation);
   return result;
 }
--- a/xpcom/threads/SchedulerGroup.h
+++ b/xpcom/threads/SchedulerGroup.h
@@ -4,16 +4,17 @@
  * 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_SchedulerGroup_h
 #define mozilla_SchedulerGroup_h
 
 #include "mozilla/AlreadyAddRefed.h"
 #include "mozilla/TaskCategory.h"
+#include "mozilla/TimeStamp.h"
 #include "nsCOMPtr.h"
 #include "nsISupportsImpl.h"
 
 class nsIEventTarget;
 class nsIRunnable;
 
 namespace mozilla {
 class AbstractThread;
@@ -33,16 +34,20 @@ class TabGroup;
 // implementations of Dispatcher.
 class SchedulerGroup
 {
 public:
   SchedulerGroup();
 
   NS_INLINE_DECL_PURE_VIRTUAL_REFCOUNTING
 
+  // This method returns true if all members of the "group" are in a
+  // "background" state.
+  virtual bool IsBackground() const { return false; }
+
   class MOZ_STACK_CLASS AutoProcessEvent final {
   public:
     AutoProcessEvent();
     ~AutoProcessEvent();
 
   private:
     SchedulerGroup* mPrevRunningDispatcher;
   };
@@ -71,16 +76,20 @@ public:
   // This method performs a safe cast. It returns null if |this| is not of the
   // requested type.
   virtual dom::TabGroup* AsTabGroup() { return nullptr; }
 
   static nsresult UnlabeledDispatch(const char* aName,
                                     TaskCategory aCategory,
                                     already_AddRefed<nsIRunnable>&& aRunnable);
 
+  static void MarkVsyncReceived();
+
+  static void MarkVsyncRan();
+
 protected:
   // Implementations are guaranteed that this method is called on the main
   // thread.
   virtual AbstractThread* AbstractMainThreadForImpl(TaskCategory aCategory);
 
   // Helper method to create an event target specific to a particular TaskCategory.
   virtual already_AddRefed<nsIEventTarget>
   CreateEventTargetFor(TaskCategory aCategory);