Bug 1676657 - Port paint phase weight histograms to WebRender r=nical

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

gfx/layers/client/ClientLayerManager.cpp

@@ -296,13 +296,8 @@ bool ClientLayerManager::EndTransactionInternal(
   // Wait for any previous async paints to complete before starting to paint
   // again. Do this outside the profiler and telemetry block so this doesn't
   // count as time spent rasterizing.
-  {
-    PaintTelemetry::AutoRecord record(
-        PaintTelemetry::Metric::FlushRasterization);
-    FlushAsyncPaints();
-  }
+  FlushAsyncPaints();
 
-  PaintTelemetry::AutoRecord record(PaintTelemetry::Metric::Rasterization);
   AUTO_PROFILER_TRACING_MARKER("Paint", "Rasterize", GRAPHICS);
   PerfStats::AutoMetricRecording<PerfStats::Metric::Rasterizing> autoRecording;
 

gfx/layers/wr/WebRenderBridgeParent.cpp

@@ -2322,6 +2322,53 @@ void WebRenderBridgeParent::NotifyDidSceneBuild(
   CompositeToTarget(mCompositorScheduler->GetLastVsyncId(), nullptr, nullptr);
 }
 
+static Telemetry::HistogramID GetHistogramId(const bool aIsLargePaint,
+                                             const bool aIsFullDisplayList) {
+  const Telemetry::HistogramID histogramIds[] = {
+      Telemetry::CONTENT_SMALL_PAINT_PHASE_WEIGHT_PARTIAL,
+      Telemetry::CONTENT_LARGE_PAINT_PHASE_WEIGHT_PARTIAL,
+      Telemetry::CONTENT_SMALL_PAINT_PHASE_WEIGHT_FULL,
+      Telemetry::CONTENT_LARGE_PAINT_PHASE_WEIGHT_FULL,
+  };
+
+  return histogramIds[(aIsFullDisplayList * 2) + aIsLargePaint];
+}
+
+static void RecordPaintPhaseTelemetry(wr::RendererStats* aStats) {
+  if (!aStats || !aStats->full_paint) {
+    return;
+  }
+
+  const double geckoDL = aStats->gecko_display_list_time;
+  const double wrDL = aStats->wr_display_list_time;
+  const double sceneBuild = aStats->scene_build_time;
+  const double frameBuild = aStats->frame_build_time;
+  const double totalMs = geckoDL + wrDL + sceneBuild + frameBuild;
+
+  // If the total time was >= 16ms, then it's likely we missed a frame due to
+  // painting. We bucket these metrics separately.
+  const bool isLargePaint = totalMs >= 16.0;
+
+  // Split the results based on display list build type, partial or full.
+  const bool isFullDisplayList = aStats->full_display_list;
+
+  auto AsPercentage = [&](const double aTimeMs) -> double {
+    MOZ_ASSERT(aTimeMs <= totalMs);
+    return (aTimeMs / totalMs) * 100.0;
+  };
+
+  auto RecordKey = [&](const nsCString& aKey, const double aTimeMs) -> void {
+    const auto val = static_cast<uint32_t>(AsPercentage(aTimeMs));
+    const auto histogramId = GetHistogramId(isLargePaint, isFullDisplayList);
+    Telemetry::Accumulate(histogramId, aKey, val);
+  };
+
+  RecordKey("dl"_ns, geckoDL);
+  RecordKey("wrdl"_ns, wrDL);
+  RecordKey("sb"_ns, sceneBuild);
+  RecordKey("fb"_ns, frameBuild);
+}
+
 Maybe<TransactionId> WebRenderBridgeParent::FlushTransactionIdsForEpoch(
     const wr::Epoch& aEpoch, const VsyncId& aCompositeStartId,
     const TimeStamp& aCompositeStartTime, const TimeStamp& aRenderStartTime,
@@ -2347,6 +2394,9 @@ Maybe<TransactionId> WebRenderBridgeParent::FlushTransactionIdsForEpoch(
           transactionId.mTxnStartTime, aCompositeStartId, aEndTime,
           fullPaintTime, mVsyncRate, transactionId.mContainsSVGGroup, true,
           aStats);
+
+      RecordPaintPhaseTelemetry(aStats);
+
       if (contentFrameTime > 200) {
         aOutputStats->AppendElement(FrameStats(
             transactionId.mId, aCompositeStartTime, aRenderStartTime, aEndTime,

gfx/layers/wr/WebRenderLayerManager.cpp

@@ -363,10 +363,6 @@ void WebRenderLayerManager::EndTransactionWithoutLayer(
 
   if (aDisplayList) {
     MOZ_ASSERT(aDisplayListBuilder && !aBackground);
-    // Record the time spent "layerizing". WR doesn't actually layerize but
-    // generating the WR display list is the closest equivalent
-    PaintTelemetry::AutoRecord record(PaintTelemetry::Metric::Layerization);
-
     mDisplayItemCache.SetDisplayList(aDisplayListBuilder, aDisplayList);
 
     mWebRenderCommandBuilder.BuildWebRenderCommands(
@@ -460,7 +456,10 @@ void WebRenderLayerManager::EndTransactionWithoutLayer(
     dlData.mRect =
         LayoutDeviceRect(LayoutDevicePoint(), LayoutDeviceSize(size));
     dlData.mScrollData.emplace(std::move(mScrollData));
-    dlData.mDLDesc.gecko_display_list_time = aGeckoDLBuildTime;
+    dlData.mDLDesc.gecko_display_list_type =
+        aDisplayListBuilder && aDisplayListBuilder->PartialBuildFailed()
+            ? wr::GeckoDisplayListType::Full(aGeckoDLBuildTime)
+            : wr::GeckoDisplayListType::Partial(aGeckoDLBuildTime);
 
     bool ret = WrBridge()->EndTransaction(
         std::move(dlData), mLatestTransactionId, containsSVGGroup,

gfx/wr/webrender/src/renderer/mod.rs

@@ -5699,6 +5699,7 @@ fn new_debug_server(_enable: bool, api_tx: Sender<ApiMsg>) -> Box<dyn DebugServe
 /// The cumulative times spent in each painting phase to generate this frame.
 #[derive(Debug, Default)]
 pub struct FullFrameStats {
+    pub full_display_list: bool,
     pub gecko_display_list_time: f64,
     pub wr_display_list_time: f64,
     pub scene_build_time: f64,
@@ -5708,6 +5709,7 @@ pub struct FullFrameStats {
 impl FullFrameStats {
     pub fn merge(&self, other: &FullFrameStats) -> Self {
         Self {
+            full_display_list: self.full_display_list || other.full_display_list,
             gecko_display_list_time: self.gecko_display_list_time + other.gecko_display_list_time,
             wr_display_list_time: self.wr_display_list_time + other.wr_display_list_time,
             scene_build_time: self.scene_build_time + other.scene_build_time,
@@ -5736,7 +5738,8 @@ pub struct RendererStats {
     pub wr_display_list_time: f64,
     pub scene_build_time: f64,
     pub frame_build_time: f64,
-    pub full_frame: bool,
+    pub full_display_list: bool,
+    pub full_paint: bool,
 }
 
 impl RendererStats {
@@ -5745,7 +5748,8 @@ impl RendererStats {
         self.wr_display_list_time = stats.wr_display_list_time;
         self.scene_build_time = stats.scene_build_time;
         self.frame_build_time = stats.frame_build_time;
-        self.full_frame = true;
+        self.full_display_list = stats.full_display_list;
+        self.full_paint = true;
     }
 }
 

gfx/wr/webrender/src/renderer/upload.rs

@@ -466,7 +466,8 @@ fn copy_from_staging_to_cache_using_draw_calls(
         wr_display_list_time: 0.0,
         scene_build_time: 0.0,
         frame_build_time: 0.0,
-        full_frame: false,
+        full_display_list: false,
+        full_paint: false,
     };
 
     let mut copy_instances = Vec::new();

gfx/wr/webrender/src/scene_builder_thread.rs

@@ -608,16 +608,17 @@ impl SceneBuilderThread {
                     display_list,
                     preserve_frame_state,
                 } => {
-                    let (gecko_display_list_time, builder_start_time_ns,
-                         builder_end_time_ns, send_time_ns) = display_list.times();
-
+                    let (builder_start_time_ns, builder_end_time_ns, send_time_ns) =
+                      display_list.times();
                     let content_send_time = profiler::ns_to_ms(precise_time_ns() - send_time_ns);
                     let dl_build_time = profiler::ns_to_ms(builder_end_time_ns - builder_start_time_ns);
                     profile.set(profiler::CONTENT_SEND_TIME, content_send_time);
                     profile.set(profiler::DISPLAY_LIST_BUILD_TIME, dl_build_time);
                     profile.set(profiler::DISPLAY_LIST_MEM, profiler::bytes_to_mb(display_list.data().len()));
 
-                    frame_stats.gecko_display_list_time += gecko_display_list_time;
+                    let (gecko_display_list_time, full_display_list) = display_list.gecko_display_list_stats();
+                    frame_stats.full_display_list = full_display_list;
+                    frame_stats.gecko_display_list_time = gecko_display_list_time;
                     frame_stats.wr_display_list_time += dl_build_time;
 
                     if self.removed_pipelines.contains(&pipeline_id) {

gfx/wr/webrender_api/src/display_list.rs

@@ -115,6 +115,18 @@ pub struct BuiltDisplayList {
     descriptor: BuiltDisplayListDescriptor,
 }
 
+#[repr(C)]
+#[derive(Copy, Clone, Deserialize, Serialize)]
+pub enum GeckoDisplayListType {
+  None,
+  Partial(f64),
+  Full(f64),
+}
+
+impl Default for GeckoDisplayListType {
+  fn default() -> Self { GeckoDisplayListType::None }
+}
+
 /// Describes the memory layout of a display list.
 ///
 /// A display list consists of some number of display list items, followed by a number of display
@@ -122,8 +134,8 @@ pub struct BuiltDisplayList {
 #[repr(C)]
 #[derive(Copy, Clone, Default, Deserialize, Serialize)]
 pub struct BuiltDisplayListDescriptor {
-    /// The time spent in painting before creating WR DL.
-    gecko_display_list_time: f64,
+    /// Gecko specific information about the display list.
+    gecko_display_list_type: GeckoDisplayListType,
     /// The first IPC time stamp: before any work has been done
     builder_start_time: u64,
     /// The second IPC time stamp: after serialization
@@ -170,7 +182,7 @@ impl DisplayListWithCache {
         self.display_list.descriptor()
     }
 
-    pub fn times(&self) -> (f64, u64, u64, u64) {
+    pub fn times(&self) -> (u64, u64, u64) {
         self.display_list.times()
     }
 
@@ -394,15 +406,22 @@ impl BuiltDisplayList {
         self.descriptor.send_start_time = time;
     }
 
-    pub fn times(&self) -> (f64, u64, u64, u64) {
+    pub fn times(&self) -> (u64, u64, u64) {
         (
-            self.descriptor.gecko_display_list_time,
             self.descriptor.builder_start_time,
             self.descriptor.builder_finish_time,
             self.descriptor.send_start_time,
         )
     }
 
+    pub fn gecko_display_list_stats(&self) -> (f64, bool) {
+        match self.descriptor.gecko_display_list_type {
+            GeckoDisplayListType::Full(duration) => (duration, true),
+            GeckoDisplayListType::Partial(duration) => (duration, false),
+            _ => (0.0, false)
+        }
+    }
+
     pub fn total_clip_nodes(&self) -> usize {
         self.descriptor.total_clip_nodes
     }
@@ -957,7 +976,7 @@ impl<'de> Deserialize<'de> for BuiltDisplayList {
         Ok(BuiltDisplayList {
             data,
             descriptor: BuiltDisplayListDescriptor {
-                gecko_display_list_time: 0.0,
+                gecko_display_list_type: GeckoDisplayListType::None,
                 builder_start_time: 0,
                 builder_finish_time: 1,
                 send_start_time: 1,
@@ -2016,7 +2035,7 @@ impl DisplayListBuilder {
             self.pipeline_id,
             BuiltDisplayList {
                 descriptor: BuiltDisplayListDescriptor {
-                    gecko_display_list_time: 0.0,
+                    gecko_display_list_type: GeckoDisplayListType::None,
                     builder_start_time: self.builder_start_time,
                     builder_finish_time: end_time,
                     send_start_time: end_time,

layout/base/nsLayoutUtils.cpp

@@ -3306,8 +3306,6 @@ nsresult nsLayoutUtils::PaintFrame(gfxContext* aRenderingContext,
     AUTO_PROFILER_TRACING_MARKER("Paint", "DisplayList", GRAPHICS);
     PerfStats::AutoMetricRecording<PerfStats::Metric::DisplayListBuilding>
         autoRecording;
-
-    PaintTelemetry::AutoRecord record(PaintTelemetry::Metric::DisplayList);
     {
       // If a scrollable container layer is created in
       // nsDisplayList::PaintForFrame, it will be the scroll parent for display

layout/painting/nsDisplayList.cpp

@@ -2335,7 +2335,7 @@ FrameLayerBuilder* nsDisplayList::BuildLayers(nsDisplayListBuilder* aBuilder,
     ContainerLayerParameters containerParameters(resolutionX, resolutionY);
 
     {
-      PaintTelemetry::AutoRecord record(PaintTelemetry::Metric::Layerization);
+      const auto start = TimeStamp::Now();
 
       root = layerBuilder->BuildContainerLayerFor(aBuilder, aLayerManager,
                                                   frame, nullptr, this,
@@ -2343,11 +2343,10 @@ FrameLayerBuilder* nsDisplayList::BuildLayers(nsDisplayListBuilder* aBuilder,
 
       aBuilder->NotifyAndClearScrollFrames();
 
-      if (!record.GetStart().IsNull() &&
-          StaticPrefs::layers_acceleration_draw_fps()) {
+      if (StaticPrefs::layers_acceleration_draw_fps()) {
         if (PaintTiming* pt =
                 ClientLayerManager::MaybeGetPaintTiming(aLayerManager)) {
-          pt->flbMs() = (TimeStamp::Now() - record.GetStart()).ToMilliseconds();
+          pt->flbMs() = (TimeStamp::Now() - start).ToMilliseconds();
         }
       }
     }
@@ -2535,9 +2534,13 @@ already_AddRefed<LayerManager> nsDisplayList::PaintRoot(
   }
 
   if (!sent) {
+    const auto start = TimeStamp::Now();
+
     FrameLayerBuilder* layerBuilder =
         BuildLayers(aBuilder, layerManager, aFlags, widgetTransaction);
 
+    Telemetry::AccumulateTimeDelta(Telemetry::PAINT_BUILD_LAYERS_TIME, start);
+
     if (!layerBuilder) {
       layerManager->SetUserData(&gLayerManagerLayerBuilder, nullptr);
       return nullptr;
@@ -10096,9 +10099,6 @@ void nsDisplayListCollection::SerializeWithCorrectZOrder(
 namespace mozilla {
 
 uint32_t PaintTelemetry::sPaintLevel = 0;
-uint32_t PaintTelemetry::sMetricLevel = 0;
-EnumeratedArray<PaintTelemetry::Metric, PaintTelemetry::Metric::COUNT, double>
-    PaintTelemetry::sMetrics;
 
 PaintTelemetry::AutoRecordPaint::AutoRecordPaint() {
   // Don't record nested paints.
@@ -10106,10 +10106,6 @@ PaintTelemetry::AutoRecordPaint::AutoRecordPaint() {
     return;
   }
 
-  // Reset metrics for a new paint.
-  for (auto& metric : sMetrics) {
-    metric = 0.0;
-  }
   mStart = TimeStamp::Now();
 }
 
@@ -10130,66 +10126,6 @@ PaintTelemetry::AutoRecordPaint::~AutoRecordPaint() {
   // Record the total time.
   Telemetry::Accumulate(Telemetry::CONTENT_PAINT_TIME,
                         static_cast<uint32_t>(totalMs));
-
-  // Helpers for recording large/small paints.
-  auto recordLarge = [=](const nsCString& aKey, double aDurationMs) -> void {
-    MOZ_ASSERT(aDurationMs <= totalMs);
-    uint32_t amount = static_cast<int32_t>((aDurationMs / totalMs) * 100.0);
-    Telemetry::Accumulate(Telemetry::CONTENT_LARGE_PAINT_PHASE_WEIGHT, aKey,
-                          amount);
-  };
-  auto recordSmall = [=](const nsCString& aKey, double aDurationMs) -> void {
-    MOZ_ASSERT(aDurationMs <= totalMs);
-    uint32_t amount = static_cast<int32_t>((aDurationMs / totalMs) * 100.0);
-    Telemetry::Accumulate(Telemetry::CONTENT_SMALL_PAINT_PHASE_WEIGHT, aKey,
-                          amount);
-  };
-
-  double dlMs = sMetrics[Metric::DisplayList];
-  double flbMs = sMetrics[Metric::Layerization];
-  double frMs = sMetrics[Metric::FlushRasterization];
-  double rMs = sMetrics[Metric::Rasterization];
-
-  // If the total time was >= 16ms, then it's likely we missed a frame due to
-  // painting. We bucket these metrics separately.
-  if (totalMs >= 16.0) {
-    recordLarge("dl"_ns, dlMs);
-    recordLarge("flb"_ns, flbMs);
-    recordLarge("fr"_ns, frMs);
-    recordLarge("r"_ns, rMs);
-  } else {
-    recordSmall("dl"_ns, dlMs);
-    recordSmall("flb"_ns, flbMs);
-    recordSmall("fr"_ns, frMs);
-    recordSmall("r"_ns, rMs);
-  }
-
-  Telemetry::Accumulate(Telemetry::PAINT_BUILD_LAYERS_TIME, flbMs);
-}
-
-PaintTelemetry::AutoRecord::AutoRecord(Metric aMetric) : mMetric(aMetric) {
-  // Don't double-record anything nested.
-  if (sMetricLevel++ > 0) {
-    return;
-  }
-
-  // Don't record inside nested paints, or outside of paints.
-  if (sPaintLevel != 1) {
-    return;
-  }
-
-  mStart = TimeStamp::Now();
-}
-
-PaintTelemetry::AutoRecord::~AutoRecord() {
-  MOZ_ASSERT(sMetricLevel != 0);
-
-  sMetricLevel--;
-  if (mStart.IsNull()) {
-    return;
-  }
-
-  sMetrics[mMetric] += (TimeStamp::Now() - mStart).ToMilliseconds();
 }
 
 }  // namespace mozilla

layout/painting/nsDisplayList.h

@@ -7409,26 +7409,6 @@ namespace mozilla {
 
 class PaintTelemetry {
  public:
-  enum class Metric {
-    DisplayList,
-    Layerization,
-    FlushRasterization,
-    Rasterization,
-    COUNT,
-  };
-
-  class AutoRecord {
-   public:
-    explicit AutoRecord(Metric aMetric);
-    ~AutoRecord();
-
-    TimeStamp GetStart() const { return mStart; }
-
-   private:
-    Metric mMetric;
-    mozilla::TimeStamp mStart;
-  };
-
   class AutoRecordPaint {
    public:
     AutoRecordPaint();
@@ -7440,8 +7420,6 @@ class PaintTelemetry {
 
  private:
   static uint32_t sPaintLevel;
-  static uint32_t sMetricLevel;
-  static mozilla::EnumeratedArray<Metric, Metric::COUNT, double> sMetrics;
 };
 
 }  // namespace mozilla

toolkit/components/telemetry/Histograms.json

@@ -14540,31 +14540,57 @@
     "description": "The reason that CONTENT_FRAME_TIME recorded a slow (>200) result, if any.",
     "labels": ["OnTime", "NoVsync", "MissedComposite", "SlowComposite", "MissedCompositeMid", "MissedCompositeLong", "MissedCompositeLow", "NoVsyncNoId"]
   },
-  "CONTENT_LARGE_PAINT_PHASE_WEIGHT": {
+  "CONTENT_SMALL_PAINT_PHASE_WEIGHT_PARTIAL": {
     "record_in_processes": ["main", "content"],
     "products": ["firefox", "fennec"],
-    "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "mwoodrow@mozilla.com"],
-    "bug_numbers": [1309442, 1518134],
-    "expires_in_version": "72",
-    "keyed": true,
-    "keys": ["dl", "flb", "fr", "r"],
-    "kind": "linear",
-    "high": 100,
-    "n_buckets": 10,
-    "description": "Percentages of times for phases in an expensive content paint relative to the time spent in the entire expensive paint. (\"dl\" = Display list, \"flb\" = Frame layer builder, \"fr\" = Flush rasterization, \"r\" = Rasterization)"
-  },
-  "CONTENT_SMALL_PAINT_PHASE_WEIGHT": {
-    "record_in_processes": ["main", "content"],
-    "products": ["firefox", "fennec"],
-    "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "mwoodrow@mozilla.com"],
+    "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "mmynttinen@mozilla.com"],
     "bug_numbers": [1430897, 1518134],
-    "expires_in_version": "72",
+    "expires_in_version": "never",
     "keyed": true,
-    "keys": ["dl", "flb", "fr", "r"],
+    "keys": ["dl", "wrdl", "sb", "fb"],
     "kind": "linear",
     "high": 100,
-    "n_buckets": 10,
-    "description": "Percentages of times for phases in a normal content paint relative to the time spent in the entire normal paint. (\"dl\" = Display list, \"flb\" = Frame layer builder, \"fr\" = Flush rasterization, \"r\" = Rasterization)"
+    "n_buckets": 12,
+    "description": "Percentages of times for phases in a normal content paint relative to the time spent in the entire normal paint. (\"dl\" = Display list, \"wrdl\" = WebRender display list, \"sb\" = Scene building, \"fb\" = Frame building)"
+  },
+  "CONTENT_LARGE_PAINT_PHASE_WEIGHT_PARTIAL": {
+    "record_in_processes": ["main", "content"],
+    "products": ["firefox", "fennec"],
+    "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "mmynttinen@mozilla.com"],
+    "bug_numbers": [1309442, 1518134],
+    "expires_in_version": "never",
+    "keyed": true,
+    "keys": ["dl", "wrdl", "sb", "fb"],
+    "kind": "linear",
+    "high": 100,
+    "n_buckets": 12,
+    "description": "Percentages of times for phases in an expensive content paint relative to the time spent in the entire expensive paint. (\"dl\" = Display list, \"wrdl\" = WebRender display list, \"sb\" = Scene building, \"fb\" = Frame building)"
+  },
+  "CONTENT_SMALL_PAINT_PHASE_WEIGHT_FULL": {
+    "record_in_processes": ["main", "content"],
+    "products": ["firefox", "fennec"],
+    "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "mmynttinen@mozilla.com"],
+    "bug_numbers": [1430897, 1518134],
+    "expires_in_version": "never",
+    "keyed": true,
+    "keys": ["dl", "wrdl", "sb", "fb"],
+    "kind": "linear",
+    "high": 100,
+    "n_buckets": 12,
+    "description": "Percentages of times for phases in a normal content paint relative to the time spent in the entire normal paint. (\"dl\" = Display list, \"wrdl\" = WebRender display list, \"sb\" = Scene building, \"fb\" = Frame building)"
+  },
+  "CONTENT_LARGE_PAINT_PHASE_WEIGHT_FULL": {
+    "record_in_processes": ["main", "content"],
+    "products": ["firefox", "fennec"],
+    "alert_emails": ["gfx-telemetry-alerts@mozilla.com", "mmynttinen@mozilla.com"],
+    "bug_numbers": [1309442, 1518134],
+    "expires_in_version": "never",
+    "keyed": true,
+    "keys": ["dl", "wrdl", "sb", "fb"],
+    "kind": "linear",
+    "high": 100,
+    "n_buckets": 12,
+    "description": "Percentages of times for phases in an expensive content paint relative to the time spent in the entire expensive paint. (\"dl\" = Display list, \"wrdl\" = WebRender display list, \"sb\" = Scene building, \"fb\" = Frame building)"
   },
   "GPU_WAIT_TIME_MS": {
     "record_in_processes": ["main", "gpu"],