Bug 1322184 - Measure time spent in content JS that causes delay in paint. r?ehsan draft
authorAndreas Farre <farre@mozilla.com>
Tue, 29 Nov 2016 14:42:04 +0100
changeset 462494 00a041463d9a773cd8383dd5af7a9a0e015e1e07
parent 459176 0aa9d60dab23367f85c5c454223b248d1d455ed0
child 542417 d85c2da379757db8286849fe5e69305aa8803805
push id41776
push userbmo:afarre@mozilla.com
push dateTue, 17 Jan 2017 16:00:13 +0000
reviewersehsan
bugs1322184
milestone53.0a1
Bug 1322184 - Measure time spent in content JS that causes delay in paint. r?ehsan MozReview-Commit-ID: HxXBqQb4yp6
dom/base/TabGroup.cpp
dom/base/TabGroup.h
layout/base/nsRefreshDriver.cpp
layout/base/nsRefreshDriver.h
toolkit/components/telemetry/Histograms.json
toolkit/components/telemetry/Telemetry.h
--- a/dom/base/TabGroup.cpp
+++ b/dom/base/TabGroup.cpp
@@ -11,16 +11,18 @@
 #include "mozilla/dom/DocGroup.h"
 #include "mozilla/ClearOnShutdown.h"
 #include "mozilla/StaticPtr.h"
 #include "mozilla/Telemetry.h"
 #include "mozilla/ThrottledEventQueue.h"
 #include "nsIDocShell.h"
 #include "nsIEffectiveTLDService.h"
 #include "nsIURI.h"
+#include "nsRefreshDriver.h"
+#include "nsThreadUtils.h"
 
 namespace mozilla {
 namespace dom {
 
 static StaticRefPtr<TabGroup> sChromeTabGroup;
 
 TabGroup::TabGroup(bool aIsChrome)
  : mLastWindowLeft(false)
@@ -230,27 +232,114 @@ TabGroup::GetTopLevelWindows()
 }
 
 NS_IMPL_ISUPPORTS(TabGroup, nsISupports)
 
 TabGroup::HashEntry::HashEntry(const nsACString* aKey)
   : nsCStringHashKey(aKey), mDocGroup(nullptr)
 {}
 
+class TelemetryWrapper : public Runnable
+{
+public:
+  TelemetryWrapper(TabGroup* aTabGroup, nsIRunnable* aRunnable,
+                   const char* aName)
+    : mTabGroup(aTabGroup)
+    , mRunnable(aRunnable)
+    , mKey(aName ? aName : "unlabelled")
+  {
+  }
+
+  NS_IMETHOD
+  Run()
+  {
+    bool allBackground = true;
+    for (nsPIDOMWindowOuter* outerWindow : mTabGroup->GetTopLevelWindows()) {
+      if (!outerWindow->IsBackground()) {
+        allBackground = false;
+      }
+    }
+
+    NS_NAMED_LITERAL_CSTRING(totalKey, "TOTAL");
+    Telemetry::AutoCancellableTimer<
+      Telemetry::CONTENT_JS_FOREGROUND_TICK_DELAY_MS>
+      foregroundTimer(mKey);
+    Telemetry::AutoCancellableTimer<
+      Telemetry::CONTENT_JS_FOREGROUND_TICK_DELAY_MS>
+      foregroundTimerTotal(totalKey);
+
+    Telemetry::AutoCancellableTimer<
+      Telemetry::CONTENT_JS_BACKGROUND_TICK_DELAY_MS>
+      backgroundTimer(mKey);
+    Telemetry::AutoCancellableTimer<
+      Telemetry::CONTENT_JS_BACKGROUND_TICK_DELAY_MS>
+      backgroundTimerTotal(totalKey);
+
+    if (allBackground) {
+      foregroundTimer.Cancel();
+      foregroundTimerTotal.Cancel();
+    } else {
+      backgroundTimer.Cancel();
+      backgroundTimerTotal.Cancel();
+    }
+
+    nsresult result = mRunnable->Run();
+
+    if (!nsRefreshDriver::IsCurrentDriverDelayed()) {
+      foregroundTimer.Cancel();
+      foregroundTimerTotal.Cancel();
+      backgroundTimer.Cancel();
+      backgroundTimerTotal.Cancel();
+    }
+
+    return result;
+  }
+
+private:
+  virtual ~TelemetryWrapper() {}
+
+  RefPtr<TabGroup> mTabGroup;
+  nsCOMPtr<nsIRunnable> mRunnable;
+  nsCString mKey;
+};
+
+already_AddRefed<nsIRunnable>
+TabGroup::MaybeWrapRunnable(already_AddRefed<nsIRunnable>&& aRunnable,
+                            const char* aName)
+{
+  nsCOMPtr<nsIRunnable> runnable(aRunnable);
+
+  if (aName) {
+    if (nsCOMPtr<nsINamed> named = do_QueryInterface(runnable)) {
+      named->SetName(aName);
+    }
+  }
+
+#ifdef EARLY_BETA_OR_EARLIER
+  if (Telemetry::CanRecordBase()) {
+    runnable = new TelemetryWrapper(this, runnable, aName);
+
+    if (aName) {
+      if (nsCOMPtr<nsINamed> named = do_QueryInterface(runnable)) {
+        named->SetName(aName);
+      }
+    }
+  }
+#endif
+
+  return runnable.forget();
+}
+
 nsresult
 TabGroup::Dispatch(const char* aName,
                    TaskCategory aCategory,
                    already_AddRefed<nsIRunnable>&& aRunnable)
 {
-  nsCOMPtr<nsIRunnable> runnable(aRunnable);
-  if (aName) {
-    if (nsCOMPtr<nsINamed> named = do_QueryInterface(runnable)) {
-      named->SetName(aName);
-    }
-  }
+  nsCOMPtr<nsIRunnable> runnable = MaybeWrapRunnable(Move(aRunnable), aName);
+
   if (NS_IsMainThread()) {
     return NS_DispatchToCurrentThread(runnable.forget());
   } else {
     return NS_DispatchToMainThread(runnable.forget());
   }
 }
 
 nsIEventTarget*
--- a/dom/base/TabGroup.h
+++ b/dom/base/TabGroup.h
@@ -119,16 +119,20 @@ public:
   // can always be used off the main thread.
   virtual nsIEventTarget* EventTargetFor(TaskCategory aCategory) const override;
 
   TabGroup* AsTabGroup() override { return this; }
 
 private:
   void EnsureThrottledEventQueues();
 
+  already_AddRefed<nsIRunnable>
+  MaybeWrapRunnable(already_AddRefed<nsIRunnable>&& aRunnable,
+                    const char* aName);
+
   ~TabGroup();
   DocGroupMap mDocGroups;
   Atomic<bool> mLastWindowLeft;
   nsTArray<nsPIDOMWindowOuter*> mWindows;
   Atomic<bool> mThrottledQueuesInitialized;
   nsCOMPtr<nsIEventTarget> mEventTargets[size_t(TaskCategory::Count)];
 };
 
--- a/layout/base/nsRefreshDriver.cpp
+++ b/layout/base/nsRefreshDriver.cpp
@@ -247,16 +247,33 @@ public:
         TimeStamp::Now()) {
       return Nothing();
     }
 
     return Some(idleEnd - TimeDuration::FromMilliseconds(
                             nsLayoutUtils::IdlePeriodDeadlineLimit()));
   }
 
+  bool AnyDriverWaitingForTransaction()
+  {
+    for (auto driver : mContentRefreshDrivers) {
+      if (driver->mWaitingForTransaction) {
+        return true;
+      }
+    }
+
+    for (auto driver : mRootRefreshDrivers) {
+      if (driver->mWaitingForTransaction) {
+        return true;
+      }
+    }
+
+    return false;
+  }
+
 protected:
   virtual void StartTimer() = 0;
   virtual void StopTimer() = 0;
   virtual void ScheduleNextTick(TimeStamp aNowTime) = 0;
 
   bool IsRootRefreshDriver(nsRefreshDriver* aDriver)
   {
     nsPresContext* pc = aDriver->GetPresContext();
@@ -2323,16 +2340,33 @@ nsRefreshDriver::GetIdleDeadlineHint()
   // sRegularRateTimer, since we consider refresh drivers attached to
   // sThrottledRateTimer to be inactive. This implies that tasks
   // resulting from a tick on the sRegularRateTimer counts as being
   // busy but tasks resulting from a tick on sThrottledRateTimer
   // counts as being idle.
   return sRegularRateTimer->GetIdleDeadlineHint();
 }
 
+/* static */ bool
+nsRefreshDriver::IsCurrentDriverDelayed()
+{
+  MOZ_ASSERT(NS_IsMainThread());
+
+  if (!sRegularRateTimer) {
+    return false;
+  }
+
+  if (sRegularRateTimer->AnyDriverWaitingForTransaction()) {
+    return TimeStamp::Now() - sRegularRateTimer->MostRecentRefresh() >
+           sRegularRateTimer->GetTimerRate();
+  }
+
+  return false;
+}
+
 void
 nsRefreshDriver::Disconnect()
 {
   MOZ_ASSERT(NS_IsMainThread());
 
   StopTimer();
 
   if (mPresContext) {
--- a/layout/base/nsRefreshDriver.h
+++ b/layout/base/nsRefreshDriver.h
@@ -360,16 +360,18 @@ public:
    * drivers attached to the current refresh driver misses a paint.
    *
    * Returning Some(TimeStamp(t)) indicates to nsThread that we will
    * be idle until. This is usually the case when we're animating
    * without skipping paints.
    */
   static mozilla::Maybe<mozilla::TimeStamp> GetIdleDeadlineHint();
 
+  static bool IsCurrentDriverDelayed();
+
   bool SkippedPaints() const
   {
     return mSkippedPaints;
   }
 
 private:
   typedef nsTObserverArray<nsARefreshObserver*> ObserverArray;
   typedef nsTHashtable<nsISupportsHashKey> RequestTable;
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -1,9 +1,8 @@
-
 {
   "A11Y_INSTANTIATED_FLAG": {
     "expires_in_version": "never",
     "kind": "flag",
     "description": "has accessibility support been instantiated"
   },
   "A11Y_CONSUMERS": {
     "expires_in_version": "default",
@@ -181,16 +180,36 @@
   },
   "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_MS": {
+    "alert_emails": ["farre@mozilla.com"],
+    "expires_in_version": "60",
+    "keyed": true,
+    "kind": "exponential",
+    "high": 60000,
+    "n_buckets": 50,
+    "bug_numbers": [1305153, 1296486],
+    "description": "Time spent executing foreground content JS causing refresh driver tick delay"
+  },
+  "CONTENT_JS_BACKGROUND_TICK_DELAY_MS": {
+    "alert_emails": ["farre@mozilla.com"],
+    "expires_in_version": "60",
+    "keyed": true,
+    "kind": "exponential",
+    "high": 60000,
+    "n_buckets": 50,
+    "bug_numbers": [1305153, 1296486],
+    "description": "Time spent executing background content JS causing refresh driver tick delay"
+  },
   "CONTENT_PROCESS_LAUNCH_TIME_MS" : {
     "alert_emails": ["bsmedberg@mozilla.com", "mconley@mozilla.com"],
     "expires_in_version": "57",
     "bug_numbers": [1304790],
     "kind": "exponential",
     "high": 64000,
     "n_buckets": 100,
     "releaseChannelCollection": "opt-out",
--- a/toolkit/components/telemetry/Telemetry.h
+++ b/toolkit/components/telemetry/Telemetry.h
@@ -242,16 +242,57 @@ public:
     counter += increment;
   }
 
 private:
   uint32_t counter;
   MOZ_DECL_USE_GUARD_OBJECT_NOTIFIER
 };
 
+template<ID id, TimerResolution res = Millisecond>
+class MOZ_RAII AutoCancellableTimer {
+public:
+  explicit AutoCancellableTimer(TimeStamp aStart = TimeStamp::Now() MOZ_GUARD_OBJECT_NOTIFIER_PARAM)
+    : isCancelled(false)
+    , start(aStart)
+  {
+    MOZ_GUARD_OBJECT_NOTIFIER_INIT;
+  }
+
+  explicit AutoCancellableTimer(const nsCString& aKey, TimeStamp aStart = TimeStamp::Now() MOZ_GUARD_OBJECT_NOTIFIER_PARAM)
+    : isCancelled(false)
+    , start(aStart)
+    , key(aKey)
+  {
+    MOZ_GUARD_OBJECT_NOTIFIER_INIT;
+  }
+
+  ~AutoCancellableTimer() {
+    if (isCancelled) {
+      return;
+    }
+
+    if (key.IsEmpty()) {
+      AccumulateDelta_impl<res>::compute(id, start);
+    } else {
+      AccumulateDelta_impl<res>::compute(id, key, start);
+    }
+  }
+
+  void Cancel() {
+    isCancelled = true;
+  }
+
+private:
+  bool isCancelled;
+  const TimeStamp start;
+  const nsCString key;
+  MOZ_DECL_USE_GUARD_OBJECT_NOTIFIER
+};
+
 /**
  * Indicates whether Telemetry base data recording is turned on. Added for future uses.
  */
 bool CanRecordBase();
 
 /**
  * Indicates whether Telemetry extended data recording is turned on.  This is intended
  * to guard calls to Accumulate when the statistic being recorded is expensive to compute.