Bug 1355480 - Add telemetry for measuring timeout execution. r=smaug, data-r=bsmedberg

Measure execution time by adding telemetry probes for tracking
foreground, tracking background, non-tracking foreground and
non-tracking background timeouts.

--HG--
extra : rebase_source : f638cc4422a777bbd093d5bbb2d5852c19b1c9d1

dom/base/TimeoutManager.cpp

@@ -7,6 +7,7 @@
 #include "TimeoutManager.h"
 #include "nsGlobalWindow.h"
 #include "mozilla/Logging.h"
+#include "mozilla/Telemetry.h"
 #include "mozilla/ThrottledEventQueue.h"
 #include "mozilla/TimeStamp.h"
 #include "nsITimeoutHandler.h"
@@ -18,6 +19,112 @@ using namespace mozilla::dom;
 
 static LazyLogModule gLog("Timeout");
 
+// Time between sampling timeout execution time.
+const uint32_t kTelemetryPeriodMS = 1000;
+
+class TimeoutTelemetry
+{
+public:
+  static TimeoutTelemetry& Get();
+  TimeoutTelemetry() : mLastCollection(TimeStamp::Now()) {}
+
+  void StartRecording(TimeStamp aNow);
+  void StopRecording();
+  void RecordExecution(TimeStamp aNow, Timeout* aTimeout, bool aIsBackground);
+  void MaybeCollectTelemetry(TimeStamp aNow);
+private:
+  struct TelemetryData
+  {
+    TimeDuration mForegroundTracking;
+    TimeDuration mForegroundNonTracking;
+    TimeDuration mBackgroundTracking;
+    TimeDuration mBackgroundNonTracking;
+  };
+
+  void Accumulate(Telemetry::HistogramID aId, TimeDuration aSample);
+
+  TelemetryData mTelemetryData;
+  TimeStamp mStart;
+  TimeStamp mLastCollection;
+};
+
+static TimeoutTelemetry gTimeoutTelemetry;
+
+/* static */ TimeoutTelemetry&
+TimeoutTelemetry::Get()
+{
+  return gTimeoutTelemetry;
+}
+
+void
+TimeoutTelemetry::StartRecording(TimeStamp aNow)
+{
+  mStart = aNow;
+}
+
+void
+TimeoutTelemetry::StopRecording()
+{
+  mStart = TimeStamp();
+}
+
+void
+TimeoutTelemetry::RecordExecution(TimeStamp aNow,
+                                  Timeout* aTimeout,
+                                  bool aIsBackground)
+{
+  if (!mStart) {
+    // If we've started a sync operation mStart might be null, in
+    // which case we should not record this piece of execution.
+    return;
+  }
+
+  TimeDuration duration = aNow - mStart;
+
+  if (aIsBackground) {
+    if (aTimeout->mIsTracking) {
+      mTelemetryData.mBackgroundTracking += duration;
+    } else {
+      mTelemetryData.mBackgroundNonTracking += duration;
+    }
+  } else {
+    if (aTimeout->mIsTracking) {
+      mTelemetryData.mForegroundTracking += duration;
+    } else {
+      mTelemetryData.mForegroundNonTracking += duration;
+    }
+  }
+}
+
+void
+TimeoutTelemetry::Accumulate(Telemetry::HistogramID aId, TimeDuration aSample)
+{
+  uint32_t sample = std::round(aSample.ToMilliseconds());
+  if (sample) {
+    Telemetry::Accumulate(aId, sample);
+  }
+}
+
+void
+TimeoutTelemetry::MaybeCollectTelemetry(TimeStamp aNow)
+{
+  if ((aNow - mLastCollection).ToMilliseconds() < kTelemetryPeriodMS) {
+    return;
+  }
+
+  Accumulate(Telemetry::TIMEOUT_EXECUTION_FG_TRACKING_MS,
+             mTelemetryData.mForegroundTracking);
+  Accumulate(Telemetry::TIMEOUT_EXECUTION_FG_MS,
+             mTelemetryData.mForegroundNonTracking);
+  Accumulate(Telemetry::TIMEOUT_EXECUTION_BG_TRACKING_MS,
+             mTelemetryData.mBackgroundTracking);
+  Accumulate(Telemetry::TIMEOUT_EXECUTION_BG_MS,
+             mTelemetryData.mBackgroundNonTracking);
+
+  mTelemetryData = TelemetryData();
+  mLastCollection = aNow;
+}
+
 static int32_t              gRunningTimeoutDepth       = 0;
 
 // The default shortest interval/timeout we permit
@@ -31,6 +138,13 @@ static int32_t gMinTrackingTimeoutValue = 0;
 static int32_t gMinTrackingBackgroundTimeoutValue = 0;
 static int32_t gTrackingTimeoutThrottlingDelay = 0;
 static bool    gAnnotateTrackingChannels = false;
+
+bool
+TimeoutManager::IsBackground() const
+{
+  return !mWindow.AsInner()->IsPlayingAudio() && mWindow.IsBackgroundInternal();
+}
+
 int32_t
 TimeoutManager::DOMMinTimeoutValue(bool aIsTracking) const {
   // First apply any back pressure delay that might be in effect.
@@ -38,8 +152,7 @@ TimeoutManager::DOMMinTimeoutValue(bool aIsTracking) const {
   // Don't use the background timeout value when the tab is playing audio.
   // Until bug 1336484 we only used to do this for pages that use Web Audio.
   // The original behavior was implemented in bug 11811073.
-  bool isBackground = !mWindow.AsInner()->IsPlayingAudio() &&
-    mWindow.IsBackgroundInternal();
+  bool isBackground = IsBackground();
   bool throttleTracking = aIsTracking && mThrottleTrackingTimeouts;
   auto minValue = throttleTracking ? (isBackground ? gMinTrackingBackgroundTimeoutValue
                                                    : gMinTrackingTimeoutValue)
@@ -1100,6 +1213,19 @@ TimeoutManager::BeginRunningTimeout(Timeout* aTimeout)
   ++gRunningTimeoutDepth;
   ++mTimeoutFiringDepth;
 
+  if (!mWindow.IsChromeWindow()) {
+    TimeStamp now = TimeStamp::Now();
+    if (currentTimeout) {
+      // If we're already running a timeout and start running another
+      // one, record the fragment duration already collected.
+      TimeoutTelemetry::Get().RecordExecution(
+        now, currentTimeout, IsBackground());
+    }
+
+    TimeoutTelemetry::Get().MaybeCollectTelemetry(now);
+    TimeoutTelemetry::Get().StartRecording(now);
+  }
+
   return currentTimeout;
 }
 
@@ -1109,6 +1235,17 @@ TimeoutManager::EndRunningTimeout(Timeout* aTimeout)
   --mTimeoutFiringDepth;
   --gRunningTimeoutDepth;
 
+  if (!mWindow.IsChromeWindow()) {
+    TimeStamp now = TimeStamp::Now();
+    TimeoutTelemetry::Get().RecordExecution(now, mRunningTimeout, IsBackground());
+
+    if (aTimeout) {
+      // If we were running a nested timeout, restart the measurement
+      // from here.
+      TimeoutTelemetry::Get().StartRecording(now);
+    }
+  }
+
   mRunningTimeout = aTimeout;
 }
 
@@ -1358,3 +1495,30 @@ TimeoutManager::MaybeStartThrottleTrackingTimout()
                                                    gTrackingTimeoutThrottlingDelay,
                                                    nsITimer::TYPE_ONE_SHOT);
 }
+
+void
+TimeoutManager::BeginSyncOperation()
+{
+  // If we're beginning a sync operation, the currently running
+  // timeout will be put on hold. To not get into an inconsistent
+  // state, where the currently running timeout appears to take time
+  // equivalent to the period of us spinning up a new event loop,
+  // record what we have and stop recording until we reach
+  // EndSyncOperation.
+  if (!mWindow.IsChromeWindow()) {
+    if (mRunningTimeout) {
+      TimeoutTelemetry::Get().RecordExecution(
+        TimeStamp::Now(), mRunningTimeout, IsBackground());
+    }
+    TimeoutTelemetry::Get().StopRecording();
+  }
+}
+
+void
+TimeoutManager::EndSyncOperation()
+{
+  // If we're running a timeout, restart the measurement from here.
+  if (!mWindow.IsChromeWindow() && mRunningTimeout) {
+    TimeoutTelemetry::Get().StartRecording(TimeStamp::Now());
+  }
+}

dom/base/TimeoutManager.h

@@ -115,10 +115,13 @@ public:
     }
   }
 
+  void BeginSyncOperation();
+  void EndSyncOperation();
 private:
   nsresult ResetTimersForThrottleReduction(int32_t aPreviousThrottleDelayMS);
   void MaybeStartThrottleTrackingTimout();
 
+  bool IsBackground() const;
 private:
   struct Timeouts {
     Timeouts()

dom/base/nsDocument.cpp

@@ -222,6 +222,7 @@
 #include "mozilla/dom/WebComponentsBinding.h"
 #include "mozilla/dom/CustomElementRegistryBinding.h"
 #include "mozilla/dom/CustomElementRegistry.h"
+#include "mozilla/dom/TimeoutManager.h"
 #include "nsFrame.h"
 #include "nsDOMCaretPosition.h"
 #include "nsIDOMHTMLTextAreaElement.h"
@@ -12981,6 +12982,9 @@ MarkDocumentTreeToBeInSyncOperation(nsIDocument* aDoc, void* aData)
     static_cast<nsCOMArray<nsIDocument>*>(aData);
   if (aDoc) {
     aDoc->SetIsInSyncOperation(true);
+    if (nsCOMPtr<nsPIDOMWindowInner> window = aDoc->GetInnerWindow()) {
+      window->TimeoutManager().BeginSyncOperation();
+    }
     documents->AppendObject(aDoc);
     aDoc->EnumerateSubDocuments(MarkDocumentTreeToBeInSyncOperation, aData);
   }
@@ -13004,6 +13008,9 @@ nsAutoSyncOperation::nsAutoSyncOperation(nsIDocument* aDoc)
 nsAutoSyncOperation::~nsAutoSyncOperation()
 {
   for (int32_t i = 0; i < mDocuments.Count(); ++i) {
+    if (nsCOMPtr<nsPIDOMWindowInner> window = mDocuments[i]->GetInnerWindow()) {
+      window->TimeoutManager().EndSyncOperation();
+    }
     mDocuments[i]->SetIsInSyncOperation(false);
   }
   nsContentUtils::SetMicroTaskLevel(mMicroTaskLevel);

toolkit/components/telemetry/Histograms.json

@@ -11252,6 +11252,47 @@
     "n_values": 99,
     "description": "Count of which layout display items are being created. Display items are created by layout to determine what content to render. A full description is above the class definition for nsDisplayItem. The list of types is kept in nsDisplayItemTypes.h."
   },
+  "TIMEOUT_EXECUTION_FG_MS":
+  {
+    "alert_emails": ["farre@mozilla.com"],
+    "bug_numbers": [1355480],
+    "expires_in_version": "61",
+    "kind": "exponential",
+    "high": 1000,
+    "n_buckets": 20,
+    "description": "Time in ms used to execute callbacks from setTimeout/setInterval, when the script belongs to a tab in the foreground and the script is not on the tracking list. Multiple events are aggregated over a 1s interval."
+  },
+  "TIMEOUT_EXECUTION_FG_TRACKING_MS":
+  {
+    "alert_emails": ["farre@mozilla.com"],
+    "bug_numbers": [1355480],
+    "expires_in_version": "61",
+    "kind": "exponential",
+    "high": 1000,
+    "n_buckets": 20,
+    "description": "Time in ms used to execute callbacks from setTimeout/setInterval, when the script belongs to a tab in the foreground and the script is on the tracking list. Multiple events are aggregated over a 1s interval."
+  },
+  "TIMEOUT_EXECUTION_BG_MS":
+  {
+    "alert_emails": ["farre@mozilla.com"],
+    "bug_numbers": [1355480],
+    "expires_in_version": "61",
+    "kind": "exponential",
+    "high": 1000,
+    "n_buckets": 20,
+    "description": "Time in ms used to execute callbacks from setTimeout/setInterval, when the script belongs to a tab in the background and the script is not on the tracking list. Multiple events are aggregated over a 1s interval."
+  },
+  "TIMEOUT_EXECUTION_BG_TRACKING_MS":
+  {
+    "alert_emails": ["farre@mozilla.com"],
+    "bug_numbers": [1355480],
+    "expires_in_version": "61",
+    "kind": "exponential",
+    "low": 1,
+    "high": 1000,
+    "n_buckets": 10,
+    "description": "Time in ms used to execute callbacks from setTimeout/setInterval, when the script belongs to a tab in the background and the script is on the tracking list. Multiple events are aggregated over a 1s interval."
+  },
   "TIME_TO_DOM_LOADING_MS": {
     "alert_emails": ["wpan@mozilla.com"],
     "expires_in_version": "60",