Bug 1355480 - Add telemetry for measuring timeout execution. r=smaug, data-r=bsmedberg
☠☠ backed out by 1e002af2f701 ☠ ☠
authorAndreas Farre <farre@mozilla.com>
Tue, 02 May 2017 07:23:00 -0400
changeset 356129 69439c0cd3e6d118681d1bb6586cb0a7b4bb85fc
parent 356128 195d6bc4e2ca19d0df4995551e3b48eac004735e
child 356130 5e01d4124eaefeb0702f31689a9223f14351368e
push id31757
push usercbook@mozilla.com
push dateWed, 03 May 2017 08:11:42 +0000
treeherdermozilla-central@82c2d17e74ef [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerssmaug
bugs1355480
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 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.
dom/base/TimeoutManager.cpp
dom/base/TimeoutManager.h
dom/base/nsDocument.cpp
toolkit/components/telemetry/Histograms.json
--- a/dom/base/TimeoutManager.cpp
+++ b/dom/base/TimeoutManager.cpp
@@ -2,49 +2,162 @@
 /* vim: set ts=8 sts=2 et sw=2 tw=80: */
 /* 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 "TimeoutManager.h"
 #include "nsGlobalWindow.h"
 #include "mozilla/Logging.h"
+#include "mozilla/Telemetry.h"
 #include "mozilla/ThrottledEventQueue.h"
 #include "mozilla/TimeStamp.h"
 #include "nsITimeoutHandler.h"
 #include "mozilla/dom/TabGroup.h"
 #include "OrderedTimeoutIterator.h"
 
 using namespace mozilla;
 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
 #define DEFAULT_MIN_TIMEOUT_VALUE 4 // 4ms
 #define DEFAULT_MIN_BACKGROUND_TIMEOUT_VALUE 1000 // 1000ms
 #define DEFAULT_MIN_TRACKING_TIMEOUT_VALUE 4 // 4ms
 #define DEFAULT_MIN_TRACKING_BACKGROUND_TIMEOUT_VALUE 1000 // 1000ms
 static int32_t gMinTimeoutValue = 0;
 static int32_t gMinBackgroundTimeoutValue = 0;
 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.
   int32_t value = std::max(mBackPressureDelayMS, 0);
   // 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)
                                    : (isBackground ? gMinBackgroundTimeoutValue
                                                    : gMinTimeoutValue);
   return std::max(minValue, value);
 }
 
@@ -1095,25 +1208,49 @@ Timeout*
 TimeoutManager::BeginRunningTimeout(Timeout* aTimeout)
 {
   Timeout* currentTimeout = mRunningTimeout;
   mRunningTimeout = 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;
 }
 
 void
 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;
 }
 
 void
 TimeoutManager::UnmarkGrayTimers()
 {
   ForEachUnorderedTimeout([](Timeout* aTimeout) {
     if (aTimeout->mScriptHandler) {
@@ -1353,8 +1490,35 @@ TimeoutManager::MaybeStartThrottleTracki
 
   nsCOMPtr<nsITimerCallback> callback =
     new ThrottleTrackingTimeoutsCallback(&mWindow);
 
   mThrottleTrackingTimeoutsTimer->InitWithCallback(callback,
                                                    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());
+  }
+}
--- a/dom/base/TimeoutManager.h
+++ b/dom/base/TimeoutManager.h
@@ -110,20 +110,23 @@ public:
   template <class Callable>
   void ForEachUnorderedTimeoutAbortable(Callable c)
   {
     if (!mNormalTimeouts.ForEachAbortable(c)) {
       mTrackingTimeouts.ForEachAbortable(c);
     }
   }
 
+  void BeginSyncOperation();
+  void EndSyncOperation();
 private:
   nsresult ResetTimersForThrottleReduction(int32_t aPreviousThrottleDelayMS);
   void MaybeStartThrottleTrackingTimout();
 
+  bool IsBackground() const;
 private:
   struct Timeouts {
     Timeouts()
       : mTimeoutInsertionPoint(nullptr)
     {
     }
 
     // Insert aTimeout into the list, before all timeouts that would
--- a/dom/base/nsDocument.cpp
+++ b/dom/base/nsDocument.cpp
@@ -217,16 +217,17 @@
 #include "mozilla/dom/ImageTracker.h"
 #include "mozilla/dom/MediaQueryList.h"
 #include "mozilla/dom/NodeFilterBinding.h"
 #include "mozilla/OwningNonNull.h"
 #include "mozilla/dom/TabChild.h"
 #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"
 #include "nsViewportInfo.h"
 #include "mozilla/StaticPtr.h"
 #include "nsITextControlElement.h"
 #include "nsIDOMNSEditableElement.h"
 #include "nsIEditor.h"
@@ -12976,16 +12977,19 @@ nsIDocument::SetId(const nsAString& aId)
 
 bool
 MarkDocumentTreeToBeInSyncOperation(nsIDocument* aDoc, void* aData)
 {
   nsCOMArray<nsIDocument>* documents =
     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);
   }
   return true;
 }
 
 nsAutoSyncOperation::nsAutoSyncOperation(nsIDocument* aDoc)
 {
@@ -12999,16 +13003,19 @@ nsAutoSyncOperation::nsAutoSyncOperation
       }
     }
   }
 }
 
 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);
 }
 
 gfxUserFontSet*
 nsIDocument::GetUserFontSet(bool aFlushUserFontSet)
 {
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -11247,16 +11247,57 @@
   "DISPLAY_ITEM_USAGE_COUNT": {
     "alert_emails": ["mchang@mozilla.com", "gfx-telemetry@mozilla.com"],
     "bug_numbers": [1353521],
     "expires_in_version": "56",
     "kind": "enumerated",
     "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",
     "kind": "exponential",
     "high": 50000,
     "n_buckets": 100,
     "bug_numbers": [1344893],
     "description": "Time in milliseconds from navigationStart to domLoading."