Bug 1322184 - Measure time spent in content JS that causes delay in paint. r=billm, data-r=bsmedberg

MozReview-Commit-ID: Iz31CKSnDdc

--HG--
extra : rebase_source : e0db2419ee2ef868d2f4d1b47d45547e55bd2036

dom/base/TabGroup.cpp

@@ -221,7 +221,7 @@ TabGroup::FindItemWithName(const nsAString& aName,
 }
 
 nsTArray<nsPIDOMWindowOuter*>
-TabGroup::GetTopLevelWindows()
+TabGroup::GetTopLevelWindows() const
 {
   MOZ_ASSERT(NS_IsMainThread());
   nsTArray<nsPIDOMWindowOuter*> array;
@@ -263,5 +263,17 @@ TabGroup::AbstractMainThreadForImpl(TaskCategory aCategory)
   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

dom/base/TabGroup.h

@@ -114,13 +114,17 @@ public:
                    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;

ipc/glue/BackgroundChildImpl.cpp

@@ -15,6 +15,7 @@
 #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"
@@ -547,6 +548,18 @@ BackgroundChildImpl::DeallocPGamepadTestChannelChild(PGamepadTestChannelChild* a
   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
 

ipc/glue/BackgroundChildImpl.h

@@ -197,6 +197,11 @@ protected:
 
   virtual bool
   DeallocPGamepadTestChannelChild(PGamepadTestChannelChild* aActor) override;
+
+#ifdef EARLY_BETA_OR_EARLIER
+  virtual void
+  OnChannelReceivedMessage(const Message& aMsg) override;
+#endif
 };
 
 class BackgroundChildImpl::ThreadLocal final

ipc/glue/MessageChannel.cpp

@@ -1088,6 +1088,8 @@ MessageChannel::OnMessageReceivedFromLink(Message&& aMsg)
     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/glue/ProtocolUtils.h

@@ -376,6 +376,7 @@ public:
     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).

layout/ipc/VsyncChild.cpp

@@ -5,6 +5,7 @@
 
 #include "VsyncChild.h"
 
+#include "mozilla/SchedulerGroup.h"
 #include "mozilla/VsyncDispatcher.h"
 #include "nsThreadUtils.h"
 
@@ -60,6 +61,8 @@ VsyncChild::RecvNotify(const TimeStamp& aVsyncTimestamp)
 {
   MOZ_ASSERT(NS_IsMainThread());
   MOZ_ASSERT(!mIsShutdown);
+
+  SchedulerGroup::MarkVsyncRan();
   if (mObservingVsync && mObserver) {
     mObserver->NotifyVsync(aVsyncTimestamp);
   }

toolkit/components/telemetry/Histograms.json

@@ -283,6 +283,53 @@
     "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",

xpcom/threads/SchedulerGroup.cpp

@@ -8,12 +8,15 @@
 
 #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
@@ -37,8 +40,9 @@ public:
     return NS_OK;
   }
 
-  NS_DECL_NSIRUNNABLE
+  bool IsBackground() const { return mDispatcher->IsBackground(); }
 
+  NS_DECL_NSIRUNNABLE
 private:
   nsCOMPtr<nsIRunnable> mRunnable;
   RefPtr<SchedulerGroup> mDispatcher;
@@ -76,6 +80,84 @@ private:
 
 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)
@@ -126,6 +208,31 @@ SchedulerGroup::UnlabeledDispatch(const char* aName,
   }
 }
 
+/* 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()
@@ -256,7 +363,12 @@ SchedulerGroup::Runnable::Run()
 
   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.

xpcom/threads/SchedulerGroup.h

@@ -9,6 +9,7 @@
 
 #include "mozilla/AlreadyAddRefed.h"
 #include "mozilla/TaskCategory.h"
+#include "mozilla/TimeStamp.h"
 #include "nsCOMPtr.h"
 #include "nsISupportsImpl.h"
 
@@ -38,6 +39,10 @@ public:
 
   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();
@@ -76,6 +81,10 @@ public:
                                     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.