Bug 1578319: Telemetry for total time spent in layout per Refresh Driver tick. r=heycam

Differential Revision: https://phabricator.services.mozilla.com/D44427

--HG--
extra : moz-landing-system : lando

layout/base/LayoutTelemetryTools.cpp

@@ -0,0 +1,178 @@
+/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
+/* 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 "mozilla/layout/LayoutTelemetryTools.h"
+
+#include "mozilla/Atomics.h"
+#include "mozilla/EnumeratedArray.h"
+#include "mozilla/EnumeratedRange.h"
+#include "mozilla/FlushType.h"
+#include "mozilla/Telemetry.h"
+
+using namespace mozilla;
+using namespace mozilla::layout_telemetry;
+
+// Returns the key name expected by telemetry. Keep to date with
+// toolkits/components/telemetry/Histograms.json.
+static nsLiteralCString SubsystemTelemetryKey(LayoutSubsystem aSubsystem) {
+  switch (aSubsystem) {
+    default:
+      MOZ_CRASH("Unexpected LayoutSubsystem value");
+    case LayoutSubsystem::Restyle:
+      return nsLiteralCString("Restyle");
+    case LayoutSubsystem::Reflow:
+      return nsLiteralCString("ReflowOther");
+    case LayoutSubsystem::ReflowFlex:
+      return nsLiteralCString("ReflowFlex");
+    case LayoutSubsystem::ReflowGrid:
+      return nsLiteralCString("ReflowGrid");
+    case LayoutSubsystem::ReflowTable:
+      return nsLiteralCString("ReflowTable");
+    case LayoutSubsystem::ReflowText:
+      return nsLiteralCString("ReflowText");
+  }
+}
+
+static AutoRecord* sCurrentRecord;
+
+static FlushKind ToKind(FlushType aFlushType) {
+  switch (aFlushType) {
+    default:
+      MOZ_CRASH("Expected FlushType::Style or FlushType::Layout");
+    case FlushType::Style:
+      return FlushKind::Style;
+    case FlushType::Layout:
+      return FlushKind::Layout;
+  }
+}
+
+namespace mozilla {
+namespace layout_telemetry {
+
+Data::Data() {
+  PodZero(&mReqsPerFlush);
+  PodZero(&mFlushesPerTick);
+  PodZero(&mLayoutSubsystemDurationMs);
+}
+
+void Data::IncReqsPerFlush(FlushType aFlushType) {
+  mReqsPerFlush[ToKind(aFlushType)]++;
+}
+
+void Data::IncFlushesPerTick(FlushType aFlushType) {
+  mFlushesPerTick[ToKind(aFlushType)]++;
+}
+
+void Data::PingReqsPerFlushTelemetry(FlushType aFlushType) {
+  auto flushKind = ToKind(aFlushType);
+  if (flushKind == FlushKind::Layout) {
+    auto styleFlushReqs = mReqsPerFlush[FlushKind::Style].value();
+    auto layoutFlushReqs = mReqsPerFlush[FlushKind::Layout].value();
+    Telemetry::Accumulate(Telemetry::PRESSHELL_REQS_PER_LAYOUT_FLUSH,
+                          NS_LITERAL_CSTRING("Style"), styleFlushReqs);
+    Telemetry::Accumulate(Telemetry::PRESSHELL_REQS_PER_LAYOUT_FLUSH,
+                          NS_LITERAL_CSTRING("Layout"), layoutFlushReqs);
+    mReqsPerFlush[FlushKind::Style] = SaturateUint8(0);
+    mReqsPerFlush[FlushKind::Layout] = SaturateUint8(0);
+  } else {
+    auto styleFlushReqs = mReqsPerFlush[FlushKind::Style].value();
+    Telemetry::Accumulate(Telemetry::PRESSHELL_REQS_PER_STYLE_FLUSH,
+                          styleFlushReqs);
+    mReqsPerFlush[FlushKind::Style] = SaturateUint8(0);
+  }
+}
+
+void Data::PingFlushPerTickTelemetry(FlushType aFlushType) {
+  auto flushKind = ToKind(aFlushType);
+  auto styleFlushes = mFlushesPerTick[FlushKind::Style].value();
+  if (styleFlushes > 0) {
+    Telemetry::Accumulate(Telemetry::PRESSHELL_FLUSHES_PER_TICK,
+                          NS_LITERAL_CSTRING("Style"), styleFlushes);
+    mFlushesPerTick[FlushKind::Style] = SaturateUint8(0);
+  }
+
+  auto layoutFlushes = mFlushesPerTick[FlushKind::Layout].value();
+  if (flushKind == FlushKind::Layout && layoutFlushes > 0) {
+    Telemetry::Accumulate(Telemetry::PRESSHELL_FLUSHES_PER_TICK,
+                          NS_LITERAL_CSTRING("Layout"), layoutFlushes);
+    mFlushesPerTick[FlushKind::Layout] = SaturateUint8(0);
+  }
+}
+
+void Data::PingTotalMsPerTickTelemetry(FlushType aFlushType) {
+  auto flushKind = ToKind(aFlushType);
+  auto range = (flushKind == FlushKind::Style)
+                   ? MakeEnumeratedRange(LayoutSubsystem::Restyle,
+                                         LayoutSubsystem::Reflow)
+                   : MakeEnumeratedRange(LayoutSubsystem::Reflow,
+                                         LayoutSubsystem::Count);
+
+  for (auto subsystem : range) {
+    auto key = SubsystemTelemetryKey(subsystem);
+    double& duration = mLayoutSubsystemDurationMs[subsystem];
+    if (duration > 0.0) {
+      Telemetry::Accumulate(Telemetry::PRESSHELL_LAYOUT_TOTAL_MS_PER_TICK, key,
+                            static_cast<uint32_t>(duration));
+      duration = 0.0;
+    }
+  }
+}
+
+void Data::PingPerTickTelemetry(FlushType aFlushType) {
+  PingFlushPerTickTelemetry(aFlushType);
+  PingTotalMsPerTickTelemetry(aFlushType);
+}
+
+AutoRecord::AutoRecord(LayoutSubsystem aSubsystem)
+    : AutoRecord(nullptr, aSubsystem) {}
+
+AutoRecord::AutoRecord(Data* aLayoutTelemetry, LayoutSubsystem aSubsystem)
+    : mParentRecord(sCurrentRecord),
+      mLayoutTelemetry(aLayoutTelemetry),
+      mSubsystem(aSubsystem),
+      mStartTime(TimeStamp::Now()),
+      mDurationMs(0.0) {
+  MOZ_ASSERT(NS_IsMainThread());
+
+  // If we're re-entering the same subsystem, don't update the current record.
+  if (mParentRecord) {
+    if (mParentRecord->mSubsystem == mSubsystem) {
+      return;
+    }
+
+    mLayoutTelemetry = mParentRecord->mLayoutTelemetry;
+    MOZ_ASSERT(mLayoutTelemetry);
+
+    // If we're entering a new subsystem, record the amount of time spent in the
+    // parent record before setting the new current record.
+    mParentRecord->mDurationMs +=
+        (mStartTime - mParentRecord->mStartTime).ToMilliseconds();
+  }
+
+  sCurrentRecord = this;
+}
+
+AutoRecord::~AutoRecord() {
+  if (sCurrentRecord != this) {
+    // If this record is not head of the list, do nothing.
+    return;
+  }
+
+  TimeStamp now = TimeStamp::Now();
+  mDurationMs += (now - mStartTime).ToMilliseconds();
+  mLayoutTelemetry->mLayoutSubsystemDurationMs[mSubsystem] += mDurationMs;
+
+  if (mParentRecord) {
+    // Restart the parent recording from this point
+    mParentRecord->mStartTime = now;
+  }
+
+  // Unlink this record from the current record list
+  sCurrentRecord = mParentRecord;
+}
+
+}  // namespace layout_telemetry
+}  // namespace mozilla

layout/base/LayoutTelemetryTools.h

@@ -0,0 +1,86 @@
+/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
+/* 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/. */
+
+/* Tools for collecting and reporting layout and style telemetry */
+
+#ifndef mozilla_LayoutTelemetryTools_h
+#define mozilla_LayoutTelemetryTools_h
+
+#include "mozilla/TimeStamp.h"
+
+#define LAYOUT_TELEMETRY_RECORD(subsystem) \
+  layout_telemetry::AutoRecord a(layout_telemetry::LayoutSubsystem::subsystem)
+
+#define LAYOUT_TELEMETRY_RECORD_BASE(subsystem)     \
+  layout_telemetry::AutoRecord a(&mLayoutTelemetry, \
+                                 layout_telemetry::LayoutSubsystem::subsystem)
+
+namespace mozilla {
+namespace layout_telemetry {
+
+enum class FlushKind : uint8_t { Style, Layout, Count };
+
+enum class LayoutSubsystem : uint8_t {
+  Restyle,
+  Reflow,
+  ReflowFlex,
+  ReflowGrid,
+  ReflowTable,
+  ReflowText,
+  Count
+};
+
+using LayoutSubsystemDurations =
+    EnumeratedArray<LayoutSubsystem, LayoutSubsystem::Count, double>;
+using LayoutFlushCount =
+    EnumeratedArray<FlushKind, FlushKind::Count, SaturateUint8>;
+
+struct Data {
+  Data();
+
+  void IncReqsPerFlush(FlushType aFlushType);
+  void IncFlushesPerTick(FlushType aFlushType);
+
+  void PingTelemetry();
+
+  // Send the current number of flush requests for aFlushType to telemetry and
+  // reset the count.
+  void PingReqsPerFlushTelemetry(FlushType aFlushType);
+
+  // Send the current non-zero number of style and layout flushes to telemetry
+  // and reset the count.
+  void PingFlushPerTickTelemetry(FlushType aFlushType);
+
+  // Send the current non-zero time spent under style and layout processing this
+  // tick to telemetry and reset the total.
+  void PingTotalMsPerTickTelemetry(FlushType aFlushType);
+
+  // Send the current per-tick telemetry for `aFlushType`.
+  void PingPerTickTelemetry(FlushType aFlushType);
+
+  LayoutFlushCount mReqsPerFlush;
+  LayoutFlushCount mFlushesPerTick;
+  LayoutSubsystemDurations mLayoutSubsystemDurationMs;
+};
+
+class AutoRecord {
+ public:
+  explicit AutoRecord(LayoutSubsystem aSubsystem);
+  AutoRecord(Data* aLayoutTelemetry, LayoutSubsystem aSubsystem);
+  ~AutoRecord();
+
+ private:
+  AutoRecord* mParentRecord;
+  Data* mLayoutTelemetry;
+  LayoutSubsystem mSubsystem;
+  TimeStamp mStartTime;
+  double mDurationMs;
+};
+
+}  // namespace layout_telemetry
+}  // namespace mozilla
+
+#endif  // !mozilla_LayoutTelemetryTools_h

layout/base/PresShell.cpp

@@ -851,8 +851,6 @@ PresShell::PresShell()
   mReflowCountMgr->SetPresShell(this);
 #endif
   mLastOSWake = mLoadBegin = TimeStamp::Now();
-  PodZero(&mReqsPerFlush);
-  PodZero(&mFlushesPerTick);
 
   PointerEventHandler::Initialize();
 }
@@ -4114,6 +4112,7 @@ void PresShell::DoFlushPendingNotifications(mozilla::ChangesToFlush aFlush) {
                                                 innerWindowID);
 #endif
       PerfStats::AutoMetricRecording<PerfStats::Metric::Styling> autoRecording;
+      LAYOUT_TELEMETRY_RECORD_BASE(Restyle);
 
       mPresContext->RestyleManager()->ProcessPendingRestyles();
     }
@@ -4145,6 +4144,7 @@ void PresShell::DoFlushPendingNotifications(mozilla::ChangesToFlush aFlush) {
                                                 innerWindowID);
 #endif
       PerfStats::AutoMetricRecording<PerfStats::Metric::Styling> autoRecording;
+      LAYOUT_TELEMETRY_RECORD_BASE(Restyle);
 
       mPresContext->RestyleManager()->ProcessPendingRestyles();
       // Clear mNeedStyleFlush here agagin to make this flag work properly for
@@ -4201,11 +4201,11 @@ void PresShell::DoFlushPendingNotifications(mozilla::ChangesToFlush aFlush) {
 
   // Update flush counters
   if (didStyleFlush) {
-    mFlushesPerTick[FlushKind::Style]++;
+    mLayoutTelemetry.IncReqsPerFlush(FlushType::Style);
   }
 
   if (didLayoutFlush) {
-    mFlushesPerTick[FlushKind::Layout]++;
+    mLayoutTelemetry.IncReqsPerFlush(FlushType::Layout);
   }
 
   // Record telemetry for the number of requests per each flush type.
@@ -4217,10 +4217,10 @@ void PresShell::DoFlushPendingNotifications(mozilla::ChangesToFlush aFlush) {
   // by `isSafeToFlush == true`.)
   if (flushType >= FlushType::InterruptibleLayout && didLayoutFlush) {
     MOZ_ASSERT(didLayoutFlush == didStyleFlush);
-    PingReqsPerFlushTelemetry(FlushKind::Layout);
+    mLayoutTelemetry.PingReqsPerFlushTelemetry(FlushType::Layout);
   } else if (flushType >= FlushType::Style && didStyleFlush) {
     MOZ_ASSERT(!didLayoutFlush);
-    PingReqsPerFlushTelemetry(FlushKind::Style);
+    mLayoutTelemetry.PingReqsPerFlushTelemetry(FlushType::Style);
   }
 }
 
@@ -9101,6 +9101,9 @@ bool PresShell::DoReflow(nsIFrame* target, bool aInterruptible,
       "Reflow", LAYOUT_Reflow,
       uri ? uri->GetSpecOrDefault() : NS_LITERAL_CSTRING("N/A"));
 #endif
+
+  LAYOUT_TELEMETRY_RECORD_BASE(Reflow);
+
   PerfStats::AutoMetricRecording<PerfStats::Metric::Reflowing> autoRecording;
 
   gfxTextPerfMetrics* tp = mPresContext->GetTextPerfMetrics();
@@ -11222,37 +11225,6 @@ void PresShell::EndPaint() {
   }
 }
 
-void PresShell::PingReqsPerFlushTelemetry(FlushKind aFlushKind) {
-  if (aFlushKind == FlushKind::Layout) {
-    auto styleFlushReqs = mReqsPerFlush[FlushKind::Style].value();
-    auto layoutFlushReqs = mReqsPerFlush[FlushKind::Layout].value();
-    Telemetry::Accumulate(Telemetry::PRESSHELL_REQS_PER_LAYOUT_FLUSH,
-                          NS_LITERAL_CSTRING("Style"), styleFlushReqs);
-    Telemetry::Accumulate(Telemetry::PRESSHELL_REQS_PER_LAYOUT_FLUSH,
-                          NS_LITERAL_CSTRING("Layout"), layoutFlushReqs);
-    mReqsPerFlush[FlushKind::Style] = SaturateUint8(0);
-    mReqsPerFlush[FlushKind::Layout] = SaturateUint8(0);
-  } else {
-    auto styleFlushReqs = mReqsPerFlush[FlushKind::Style].value();
-    Telemetry::Accumulate(Telemetry::PRESSHELL_REQS_PER_STYLE_FLUSH,
-                          styleFlushReqs);
-    mReqsPerFlush[FlushKind::Style] = SaturateUint8(0);
-  }
-}
-
-void PresShell::PingFlushPerTickTelemetry(FlushType aFlushType) {
-  MOZ_ASSERT(aFlushType == FlushType::Style || aFlushType == FlushType::Layout);
-  auto styleFlushes = mFlushesPerTick[FlushKind::Style].value();
-  if (styleFlushes > 0) {
-    Telemetry::Accumulate(Telemetry::PRESSHELL_FLUSHES_PER_TICK,
-                          NS_LITERAL_CSTRING("Style"), styleFlushes);
-    mFlushesPerTick[FlushKind::Style] = SaturateUint8(0);
-  }
-
-  auto layoutFlushes = mFlushesPerTick[FlushKind::Layout].value();
-  if (aFlushType == FlushType::Layout && layoutFlushes > 0) {
-    Telemetry::Accumulate(Telemetry::PRESSHELL_FLUSHES_PER_TICK,
-                          NS_LITERAL_CSTRING("Layout"), layoutFlushes);
-    mFlushesPerTick[FlushKind::Layout] = SaturateUint8(0);
-  }
+void PresShell::PingPerTickTelemetry(FlushType aFlushType) {
+  mLayoutTelemetry.PingPerTickTelemetry(aFlushType);
 }

layout/base/PresShell.h

@@ -23,7 +23,6 @@
 #include "mozilla/EventForwards.h"
 #include "mozilla/FlushType.h"
 #include "mozilla/MemoryReporting.h"
-#include "mozilla/Saturate.h"
 #include "mozilla/ScrollTypes.h"
 #include "mozilla/ServoStyleSet.h"
 #include "mozilla/ServoStyleConsts.h"
@@ -33,6 +32,7 @@
 #include "mozilla/WeakPtr.h"
 #include "mozilla/dom/HTMLDocumentBinding.h"
 #include "mozilla/layers/FocusTarget.h"
+#include "mozilla/layout/LayoutTelemetryTools.h"
 #include "nsChangeHint.h"
 #include "nsClassHashtable.h"
 #include "nsColor.h"
@@ -2794,15 +2794,10 @@ class PresShell final : public nsStubDocumentObserver,
   nsIFrame* mDrawEventTargetFrame = nullptr;
 #endif  // #ifdef DEBUG
 
-  enum class FlushKind : uint8_t { Style, Layout, Count };
-
-  // Send the current number of flush requests for aFlushType to telemetry and
-  // reset the count.
-  void PingReqsPerFlushTelemetry(FlushKind aFlushKind);
-
-  // Send the current non-zero number of style and layout flushes to telemetry
-  // and reset the count.
-  void PingFlushPerTickTelemetry(FlushType aFlushType);
+  // Send, and reset, the current per tick telemetry. This includes:
+  // * non-zero number of style and layout flushes
+  // * non-zero ms duration spent in style and reflow since the last tick.
+  void PingPerTickTelemetry(FlushType aFlushType);
 
  private:
   // IMPORTANT: The ownership implicit in the following member variables
@@ -3167,8 +3162,7 @@ class PresShell final : public nsStubDocumentObserver,
 
   static bool sProcessInteractable;
 
-  EnumeratedArray<FlushKind, FlushKind::Count, SaturateUint8> mReqsPerFlush;
-  EnumeratedArray<FlushKind, FlushKind::Count, SaturateUint8> mFlushesPerTick;
+  layout_telemetry::Data mLayoutTelemetry;
 };
 
 NS_DEFINE_STATIC_IID_ACCESSOR(PresShell, NS_PRESSHELL_IID)

layout/base/PresShellInlines.h

@@ -27,7 +27,7 @@ void PresShell::SetNeedLayoutFlush() {
   }
 #endif
 
-  mReqsPerFlush[FlushKind::Layout]++;
+  mLayoutTelemetry.IncReqsPerFlush(FlushType::Layout);
 }
 
 void PresShell::SetNeedStyleFlush() {
@@ -44,7 +44,7 @@ void PresShell::SetNeedStyleFlush() {
   }
 #endif
 
-  mReqsPerFlush[FlushKind::Style]++;
+  mLayoutTelemetry.IncReqsPerFlush(FlushType::Layout);
 }
 
 void PresShell::EnsureStyleFlush() {

layout/base/moz.build

@@ -88,6 +88,10 @@ EXPORTS.mozilla += [
     'StaticPresData.h',
 ]
 
+EXPORTS.mozilla.layout += [
+    'LayoutTelemetryTools.h',
+]
+
 UNIFIED_SOURCES += [
     'AccessibleCaret.cpp',
     'AccessibleCaretEventHub.cpp',
@@ -95,6 +99,7 @@ UNIFIED_SOURCES += [
     'GeckoMVMContext.cpp',
     'GeometryUtils.cpp',
     'LayoutLogging.cpp',
+    'LayoutTelemetryTools.cpp',
     'MobileViewportManager.cpp',
     'MotionPathUtils.cpp',
     'nsBidi.cpp',

layout/base/nsRefreshDriver.cpp

@@ -1996,9 +1996,8 @@ void nsRefreshDriver::Tick(VsyncId aId, TimeStamp aNowTime) {
           presShell->NotifyFontFaceSetOnRefresh();
           mNeedToRecomputeVisibility = true;
 
-          // Record the telemetry for the # of flushes that occurred between
-          // ticks.
-          presShell->PingFlushPerTickTelemetry(FlushType::Style);
+          // Record the telemetry for events that occurred between ticks.
+          presShell->PingPerTickTelemetry(FlushType::Style);
         }
       }
     } else if (i == 2) {
@@ -2025,9 +2024,8 @@ void nsRefreshDriver::Tick(VsyncId aId, TimeStamp aNowTime) {
         presShell->NotifyFontFaceSetOnRefresh();
         mNeedToRecomputeVisibility = true;
 
-        // Record the telemetry for the # of flushes that occured between
-        // ticks.
-        presShell->PingFlushPerTickTelemetry(FlushType::Layout);
+        // Record the telemetry for events that occurred between ticks.
+        presShell->PingPerTickTelemetry(FlushType::Layout);
       }
     }
 

toolkit/components/telemetry/Histograms.json

@@ -15591,5 +15591,25 @@
     "n_buckets": 100,
     "bug_numbers": [1564179],
     "description": "milliseconds to complete a TLS handshake that used delegated credentials"
+  },
+  "PRESSHELL_LAYOUT_TOTAL_MS_PER_TICK": {
+    "record_in_processes": ["main", "content"],
+    "products": ["firefox", "fennec", "geckoview"],
+    "alert_emails": ["dglastonbury@mozilla.com"],
+    "bug_numbers": [1578319],
+    "expires_in_version": "76",
+    "keyed": true,
+    "keys": [
+      "Restyle",
+      "ReflowOther",
+      "ReflowFlex",
+      "ReflowGrid",
+      "ReflowTable",
+      "ReflowText"
+    ],
+    "kind": "exponential",
+    "high": 1000,
+    "n_buckets": 50,
+    "description": "Time in milliseconds spent in the layout system per Refresh Driver tick."
   }
 }