Bug 1700642 - Part 1: Track per frame paint phase durations r=nical

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

gfx/layers/wr/WebRenderLayerManager.cpp

@@ -322,7 +322,8 @@ void WebRenderLayerManager::EndTransaction(DrawPaintedLayerCallback aCallback,
 
 void WebRenderLayerManager::EndTransactionWithoutLayer(
     nsDisplayList* aDisplayList, nsDisplayListBuilder* aDisplayListBuilder,
-    WrFiltersHolder&& aFilters, WebRenderBackgroundData* aBackground) {
+    WrFiltersHolder&& aFilters, WebRenderBackgroundData* aBackground,
+    const double aGeckoDLBuildTime) {
   AUTO_PROFILER_TRACING_MARKER("Paint", "RenderLayers", GRAPHICS);
 
   // Since we don't do repeat transactions right now, just set the time
@@ -459,6 +460,7 @@ void WebRenderLayerManager::EndTransactionWithoutLayer(
     dlData.mRect =
         LayoutDeviceRect(LayoutDevicePoint(), LayoutDeviceSize(size));
     dlData.mScrollData.emplace(std::move(mScrollData));
+    dlData.mDLDesc.gecko_display_list_time = aGeckoDLBuildTime;
 
     bool ret = WrBridge()->EndTransaction(
         std::move(dlData), mLatestTransactionId, containsSVGGroup,

gfx/layers/wr/WebRenderLayerManager.h

@@ -82,10 +82,11 @@ class WebRenderLayerManager final : public LayerManager {
                                   const nsCString& aURL) override;
   bool BeginTransaction(const nsCString& aURL) override;
   bool EndEmptyTransaction(EndTransactionFlags aFlags = END_DEFAULT) override;
-  void EndTransactionWithoutLayer(
+  void EndTransactionWithoutLayer(nsDisplayList* aDisplayList,
-      nsDisplayList* aDisplayList, nsDisplayListBuilder* aDisplayListBuilder,
+                                  nsDisplayListBuilder* aDisplayListBuilder,
-      WrFiltersHolder&& aFilters = WrFiltersHolder(),
+                                  WrFiltersHolder&& aFilters,
-      WebRenderBackgroundData* aBackground = nullptr);
+                                  WebRenderBackgroundData* aBackground,
+                                  const double aGeckoDLBuildTime);
   void EndTransaction(DrawPaintedLayerCallback aCallback, void* aCallbackData,
                       EndTransactionFlags aFlags = END_DEFAULT) override;
 

gfx/wr/webrender/src/internal_types.rs

@@ -9,7 +9,7 @@ use api;
 use crate::render_api::DebugCommand;
 use crate::composite::NativeSurfaceOperation;
 use crate::device::TextureFilter;
-use crate::renderer::PipelineInfo;
+use crate::renderer::{FullFrameStats, PipelineInfo};
 use crate::gpu_cache::GpuCacheUpdateList;
 use crate::frame_builder::Frame;
 use crate::profiler::TransactionProfile;
@@ -504,6 +504,7 @@ pub struct RenderedDocument {
     pub frame: Frame,
     pub is_new_scene: bool,
     pub profile: TransactionProfile,
+    pub frame_stats: Option<FullFrameStats>
 }
 
 pub enum DebugOutput {

gfx/wr/webrender/src/render_backend.rs

@@ -40,7 +40,7 @@ use crate::prim_store::{PrimitiveInstanceKind, PrimTemplateCommonData, Primitive
 use crate::prim_store::interned::*;
 use crate::profiler::{self, TransactionProfile};
 use crate::render_task_graph::RenderTaskGraphBuilder;
-use crate::renderer::{AsyncPropertySampler, PipelineInfo};
+use crate::renderer::{AsyncPropertySampler, FullFrameStats, PipelineInfo};
 use crate::resource_cache::ResourceCache;
 #[cfg(feature = "replay")]
 use crate::resource_cache::PlainCacheOwn;
@@ -471,6 +471,7 @@ struct Document {
     dirty_rects_are_valid: bool,
 
     profile: TransactionProfile,
+    frame_stats: Option<FullFrameStats>,
 }
 
 impl Document {
@@ -512,6 +513,7 @@ impl Document {
             dirty_rects_are_valid: true,
             profile: TransactionProfile::new(),
             rg_builder: RenderTaskGraphBuilder::new(),
+            frame_stats: None,
         }
     }
 
@@ -606,8 +608,9 @@ impl Document {
         debug_flags: DebugFlags,
         tile_cache_logger: &mut TileCacheLogger,
         tile_caches: &mut FastHashMap<SliceId, Box<TileCacheInstance>>,
+        frame_stats: Option<FullFrameStats>
     ) -> RenderedDocument {
-        self.profile.start_time(profiler::FRAME_BUILDING_TIME);
+        let frame_build_start_time = precise_time_ns();
 
         let accumulated_scale_factor = self.view.accumulated_scale_factor();
         let pan = self.view.frame.pan.to_f32() / accumulated_scale_factor;
@@ -647,12 +650,20 @@ impl Document {
         let is_new_scene = self.has_built_scene;
         self.has_built_scene = false;
 
-        self.profile.end_time(profiler::FRAME_BUILDING_TIME);
+        let frame_build_time_ms =
+            profiler::ns_to_ms(precise_time_ns() - frame_build_start_time);
+        self.profile.set(profiler::FRAME_BUILDING_TIME, frame_build_time_ms);
+
+        let frame_stats = frame_stats.map(|mut stats| {
+            stats.frame_build_time += frame_build_time_ms;
+            stats
+        });
 
         RenderedDocument {
             frame,
             is_new_scene,
             profile: self.profile.take_and_reset(),
+            frame_stats: frame_stats
         }
     }
 
@@ -942,11 +953,16 @@ impl RenderBackend {
            let has_built_scene = txn.built_scene.is_some();
 
             if let Some(doc) = self.documents.get_mut(&txn.document_id) {
-
                 doc.removed_pipelines.append(&mut txn.removed_pipelines);
                 doc.view.scene = txn.view;
                 doc.profile.merge(&mut txn.profile);
 
+                doc.frame_stats = if let Some(stats) = &doc.frame_stats {
+                    Some(stats.merge(&txn.frame_stats))
+                } else {
+                    Some(txn.frame_stats)
+                };
+
                 if let Some(built_scene) = txn.built_scene.take() {
                     doc.new_async_scene_ready(
                         built_scene,
@@ -1505,12 +1521,15 @@ impl RenderBackend {
             let (pending_update, rendered_document) = {
                 let frame_build_start_time = precise_time_ns();
 
+                let frame_stats = doc.frame_stats.take();
+
                 let rendered_document = doc.build_frame(
                     &mut self.resource_cache,
                     &mut self.gpu_cache,
                     self.debug_flags,
                     &mut self.tile_cache_logger,
                     &mut self.tile_caches,
+                    frame_stats
                 );
 
                 debug!("generated frame for document {:?} with {} passes",
@@ -1722,6 +1741,7 @@ impl RenderBackend {
                     self.debug_flags,
                     &mut self.tile_cache_logger,
                     &mut self.tile_caches,
+                    None,
                 );
                 // After we rendered the frames, there are pending updates to both
                 // GPU cache and resources. Instead of serializing them, we are going to make sure
@@ -1964,6 +1984,7 @@ impl RenderBackend {
                         dirty_rects_are_valid: false,
                         profile: TransactionProfile::new(),
                         rg_builder: RenderTaskGraphBuilder::new(),
+                        frame_stats: FullFrameStats
                     };
                     entry.insert(doc);
                 }

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

@@ -2230,6 +2230,12 @@ impl Renderer {
         results.stats.gpu_cache_upload_time = self.gpu_cache_upload_time;
         self.gpu_cache_upload_time = 0.0;
 
+        if let Some(stats) = active_doc.frame_stats.take() {
+          // Copy the full frame stats to RendererStats
+          results.stats.merge(&stats);
+
+        }
+
         // Note: this clears the values in self.profile.
         self.profiler.set_counters(&mut self.profile);
 
@@ -5580,6 +5586,30 @@ fn new_debug_server(_enable: bool, api_tx: Sender<ApiMsg>) -> Box<dyn DebugServe
     Box::new(NoopDebugServer::new(api_tx))
 }
 
+/// The cumulative times spent in each painting phase to generate this frame.
+#[derive(Debug, Default)]
+pub struct FullFrameStats {
+    pub gecko_display_list_time: f64,
+    pub wr_display_list_time: f64,
+    pub scene_build_time: f64,
+    pub frame_build_time: f64,
+}
+
+impl FullFrameStats {
+    pub fn merge(&self, other: &FullFrameStats) -> Self {
+        Self {
+            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,
+            frame_build_time: self.frame_build_time + other.frame_build_time
+        }
+    }
+
+    pub fn total(&self) -> f64 {
+      self.gecko_display_list_time + self.wr_display_list_time + self.scene_build_time + self.frame_build_time
+    }
+}
+
 /// Some basic statistics about the rendered scene, used in Gecko, as
 /// well as in wrench reftests to ensure that tests are batching and/or
 /// allocating on render targets as we expect them to.
@@ -5592,6 +5622,21 @@ pub struct RendererStats {
     pub texture_upload_mb: f64,
     pub resource_upload_time: f64,
     pub gpu_cache_upload_time: f64,
+    pub gecko_display_list_time: f64,
+    pub wr_display_list_time: f64,
+    pub scene_build_time: f64,
+    pub frame_build_time: f64,
+    pub full_frame: bool,
+}
+
+impl RendererStats {
+    pub fn merge(&mut self, stats: &FullFrameStats) {
+        self.gecko_display_list_time = stats.gecko_display_list_time;
+        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;
+    }
 }
 
 /// Return type from render(), which contains some repr(C) statistics as well as

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

@@ -462,6 +462,11 @@ fn copy_from_staging_to_cache_using_draw_calls(
         texture_upload_mb: 0.0,
         resource_upload_time: 0.0,
         gpu_cache_upload_time: 0.0,
+        gecko_display_list_time: 0.0,
+        wr_display_list_time: 0.0,
+        scene_build_time: 0.0,
+        frame_build_time: 0.0,
+        full_frame: false,
     };
 
     let mut copy_instances = Vec::new();

gfx/wr/webrender/src/scene_builder_thread.rs

@@ -28,7 +28,7 @@ use crate::prim_store::picture::Picture;
 use crate::prim_store::text_run::TextRun;
 use crate::profiler::{self, TransactionProfile};
 use crate::render_backend::SceneView;
-use crate::renderer::{PipelineInfo, SceneBuilderHooks};
+use crate::renderer::{FullFrameStats, PipelineInfo, SceneBuilderHooks};
 use crate::scene::{Scene, BuiltScene, SceneStats};
 use std::iter;
 use time::precise_time_ns;
@@ -72,6 +72,7 @@ pub struct BuiltTransaction {
     pub invalidate_rendered_frame: bool,
     pub discard_frame_state_for_pipelines: Vec<PipelineId>,
     pub profile: TransactionProfile,
+    pub frame_stats: FullFrameStats,
 }
 
 #[cfg(feature = "replay")]
@@ -461,6 +462,7 @@ impl SceneBuilderThread {
                 notifications: Vec::new(),
                 interner_updates,
                 profile: TransactionProfile::new(),
+                frame_stats: FrameStats::default(),
             })];
 
             self.forward_built_transactions(txns);
@@ -572,11 +574,12 @@ impl SceneBuilderThread {
 
         let mut profile = txn.profile.take();
 
-        profile.start_time(profiler::SCENE_BUILD_TIME);
+        let scene_build_start = precise_time_ns();
-
         let mut discard_frame_state_for_pipelines = Vec::new();
         let mut removed_pipelines = Vec::new();
         let mut rebuild_scene = false;
+        let mut frame_stats = FullFrameStats::default();
+
         for message in txn.scene_ops.drain(..) {
             match message {
                 SceneMsg::UpdateEpoch(pipeline_id, epoch) => {
@@ -600,8 +603,8 @@ impl SceneBuilderThread {
                     display_list,
                     preserve_frame_state,
                 } => {
-                    let (builder_start_time_ns, builder_end_time_ns, send_time_ns) =
+                    let (gecko_display_list_time, builder_start_time_ns,
-                        display_list.times();
+                         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);
@@ -609,6 +612,9 @@ impl SceneBuilderThread {
                     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;
+                    frame_stats.wr_display_list_time += dl_build_time;
+
                     if self.removed_pipelines.contains(&pipeline_id) {
                         continue;
                     }
@@ -670,8 +676,11 @@ impl SceneBuilderThread {
             built_scene = Some(built);
         }
 
-        profile.end_time(profiler::SCENE_BUILD_TIME);
+        let scene_build_time_ms =
+            profiler::ns_to_ms(precise_time_ns() - scene_build_start);
+        profile.set(profiler::SCENE_BUILD_TIME, scene_build_time_ms);
 
+        frame_stats.scene_build_time += scene_build_time_ms;
 
         if !txn.blob_requests.is_empty() {
             profile.start_time(profiler::BLOB_RASTERIZATION_TIME);
@@ -707,6 +716,7 @@ impl SceneBuilderThread {
             notifications: txn.notifications,
             interner_updates,
             profile,
+            frame_stats,
         })
     }
 

gfx/wr/webrender_api/src/display_list.rs

@@ -122,6 +122,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,
     /// The first IPC time stamp: before any work has been done
     builder_start_time: u64,
     /// The second IPC time stamp: after serialization
@@ -168,6 +170,10 @@ impl DisplayListWithCache {
         self.display_list.descriptor()
     }
 
+    pub fn times(&self) -> (f64, u64, u64, u64) {
+        self.display_list.times()
+    }
+
     pub fn data(&self) -> &[u8] {
         self.display_list.data()
     }
@@ -383,8 +389,9 @@ impl BuiltDisplayList {
         self.descriptor.send_start_time = time;
     }
 
-    pub fn times(&self) -> (u64, u64, u64) {
+    pub fn times(&self) -> (f64, u64, u64, u64) {
         (
+            self.descriptor.gecko_display_list_time,
             self.descriptor.builder_start_time,
             self.descriptor.builder_finish_time,
             self.descriptor.send_start_time,
@@ -1984,6 +1991,7 @@ impl DisplayListBuilder {
             self.pipeline_id,
             BuiltDisplayList {
                 descriptor: BuiltDisplayListDescriptor {
+                    gecko_display_list_time: 0.0,
                     builder_start_time: self.builder_start_time,
                     builder_finish_time: end_time,
                     send_start_time: end_time,

layout/base/PresShell.cpp

@@ -5096,7 +5096,7 @@ already_AddRefed<SourceSurface> PresShell::PaintRangePaintInfo(
     aArea.MoveBy(-rangeInfo->mRootOffset.x, -rangeInfo->mRootOffset.y);
     nsRegion visible(aArea);
     RefPtr<LayerManager> layerManager = rangeInfo->mList.PaintRoot(
-        &rangeInfo->mBuilder, ctx, nsDisplayList::PAINT_DEFAULT);
+        &rangeInfo->mBuilder, ctx, nsDisplayList::PAINT_DEFAULT, Nothing());
     aArea.MoveBy(rangeInfo->mRootOffset.x, rangeInfo->mRootOffset.y);
   }
 
@@ -6435,7 +6435,7 @@ void PresShell::Paint(nsView* aViewToPaint, const nsRegion& aDirtyRegion,
 
     MaybeSetupTransactionIdAllocator(layerManager, presContext);
     layerManager->AsWebRenderLayerManager()->EndTransactionWithoutLayer(
-        nullptr, nullptr, std::move(wrFilters), &data);
+        nullptr, nullptr, std::move(wrFilters), &data, 0);
     return;
   }
 

layout/base/nsLayoutUtils.cpp

@@ -3429,8 +3429,11 @@ nsresult nsLayoutUtils::PaintFrame(gfxContext* aRenderingContext,
   MOZ_ASSERT(updateState != PartialUpdateResult::Failed);
   builder->Check();
 
-  Telemetry::AccumulateTimeDelta(Telemetry::PAINT_BUILD_DISPLAYLIST_TIME,
+  const double geckoDLBuildTime =
-                                 startBuildDisplayList);
+      (TimeStamp::Now() - startBuildDisplayList).ToMilliseconds();
+
+  Telemetry::Accumulate(Telemetry::PAINT_BUILD_DISPLAYLIST_TIME,
+                        geckoDLBuildTime);
 
   bool consoleNeedsDisplayList =
       (gfxUtils::DumpDisplayList() || gfxEnv::DumpPaint()) &&
@@ -3483,8 +3486,8 @@ nsresult nsLayoutUtils::PaintFrame(gfxContext* aRenderingContext,
 #endif
 
   TimeStamp paintStart = TimeStamp::Now();
-  RefPtr<LayerManager> layerManager =
+  RefPtr<LayerManager> layerManager = list->PaintRoot(
-      list->PaintRoot(builder, aRenderingContext, flags);
+      builder, aRenderingContext, flags, Some(geckoDLBuildTime));
   Telemetry::AccumulateTimeDelta(Telemetry::PAINT_RASTERIZE_TIME, paintStart);
 
   if (builder->IsPaintingToWindow()) {

layout/painting/nsDisplayList.cpp

@@ -2385,7 +2385,8 @@ FrameLayerBuilder* nsDisplayList::BuildLayers(nsDisplayListBuilder* aBuilder,
  * root of the layer manager, drawing into the PaintedLayers.
  */
 already_AddRefed<LayerManager> nsDisplayList::PaintRoot(
-    nsDisplayListBuilder* aBuilder, gfxContext* aCtx, uint32_t aFlags) {
+    nsDisplayListBuilder* aBuilder, gfxContext* aCtx, uint32_t aFlags,
+    mozilla::Maybe<double> aDisplayListBuildTime) {
   AUTO_PROFILER_LABEL("nsDisplayList::PaintRoot", GRAPHICS);
 
   RefPtr<LayerManager> layerManager;
@@ -2449,7 +2450,8 @@ already_AddRefed<LayerManager> nsDisplayList::PaintRoot(
       }
 
       wrManager->EndTransactionWithoutLayer(this, aBuilder,
-                                            std::move(wrFilters));
+                                            std::move(wrFilters), nullptr,
+                                            aDisplayListBuildTime.valueOr(0.0));
     }
 
     // For layers-free mode, we check the invalidation state bits in the

layout/painting/nsDisplayList.h

@@ -3624,8 +3624,9 @@ class nsDisplayList {
     PAINT_COMPRESSED = 0x10,
     PAINT_IDENTICAL_DISPLAY_LIST = 0x20
   };
-  already_AddRefed<LayerManager> PaintRoot(nsDisplayListBuilder* aBuilder,
+  already_AddRefed<LayerManager> PaintRoot(
-                                           gfxContext* aCtx, uint32_t aFlags);
+      nsDisplayListBuilder* aBuilder, gfxContext* aCtx, uint32_t aFlags,
+      mozilla::Maybe<double> aDisplayListBuildTime);
 
   mozilla::FrameLayerBuilder* BuildLayers(nsDisplayListBuilder* aBuilder,
                                           LayerManager* aLayerManager,