Measure Wasted Visual Update Time Before First Surface Activation

Currently we have inefficient Renderer startup. We are performing a
series of Surface Syncs, changing visual properties, before any content
is shown. Depending on the platform it appears that we are doing 3-5
passes of this. Instead of just one single update of all the correct
visual properties.

Blink is attempting to update the visual state, including layout, in
response to each of these.

To understand how much of a performance hit this is, we are going to
report the time spent performing these updates for each LocalSurfaceId.
Then reporting the difference when the First Surface is actually
activated and displayed.

This should let us better understand the impact of this, and measure
improvements in follow-up work.

(cherry picked from commit c850478)

Bug: 1245652
Change-Id: I1853b8c24f2dfeed81a59046d0421aef8ca64d30
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3615369
Reviewed-by: Kyle Charbonneau <kylechar@chromium.org>
Reviewed-by: Ken Buchanan <kenrb@chromium.org>
Reviewed-by: Philip Rogers <pdr@chromium.org>
Commit-Queue: Jonathan Ross <jonross@chromium.org>
Cr-Original-Commit-Position: refs/heads/main@{#1004873}
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3664003
Bot-Commit: Rubber Stamper <rubber-stamper@appspot.gserviceaccount.com>
Auto-Submit: Jonathan Ross <jonross@chromium.org>
Cr-Commit-Position: refs/branch-heads/5060@{#223}
Cr-Branched-From: b83393d-refs/heads/main@{#1002911}

cc/mojom/render_frame_metadata.mojom

@@ -4,6 +4,7 @@
 
 module cc.mojom;
 
+import "mojo/public/mojom/base/time.mojom";
 import "services/viz/public/mojom/compositing/local_surface_id.mojom";
 import "services/viz/public/mojom/compositing/selection.mojom";
 import "services/viz/public/mojom/compositing/vertical_scroll_direction.mojom";
@@ -79,6 +80,14 @@ struct RenderFrameMetadata {
 
   viz.mojom.VerticalScrollDirection new_vertical_scroll_direction;
 
+  // The cumulative time spent performing visual updates since the last commit.
+  // Tracked for all `local_surface_id` before this one.
+  mojo_base.mojom.TimeDelta previous_surfaces_visual_update_duration;
+
+  // The cumulative time spend performing visual updates for the current
+  // `local_surface_id` since the last commit.
+  mojo_base.mojom.TimeDelta current_surface_visual_update_duration;
+
   // Used to position Android bottom bar, whose position is computed by the
   // renderer compositor.
   [EnableIf=is_android]

cc/mojom/render_frame_metadata_mojom_traits.cc

@@ -5,6 +5,7 @@
 #include "cc/mojom/render_frame_metadata_mojom_traits.h"
 
 #include "build/build_config.h"
+#include "mojo/public/cpp/base/time_mojom_traits.h"
 #include "services/viz/public/cpp/compositing/selection_mojom_traits.h"
 #include "services/viz/public/cpp/compositing/vertical_scroll_direction_mojom_traits.h"
 #include "ui/gfx/geometry/mojom/geometry_mojom_traits.h"
@@ -55,7 +56,11 @@ bool StructTraits<
          data.ReadViewportSizeInPixels(&out->viewport_size_in_pixels) &&
          data.ReadLocalSurfaceId(&out->local_surface_id) &&
          data.ReadNewVerticalScrollDirection(
-             &out->new_vertical_scroll_direction);
+             &out->new_vertical_scroll_direction) &&
+         data.ReadPreviousSurfacesVisualUpdateDuration(
+             &out->previous_surfaces_visual_update_duration) &&
+         data.ReadCurrentSurfaceVisualUpdateDuration(
+             &out->current_surface_visual_update_duration);
 }
 
 }  // namespace mojo

cc/mojom/render_frame_metadata_mojom_traits.h

@@ -96,6 +96,16 @@ struct COMPONENT_EXPORT(CC_SHARED_MOJOM_TRAITS)
     return metadata.new_vertical_scroll_direction;
   }
 
+  static base::TimeDelta previous_surfaces_visual_update_duration(
+      const cc::RenderFrameMetadata& metadata) {
+    return metadata.previous_surfaces_visual_update_duration;
+  }
+
+  static base::TimeDelta current_surface_visual_update_duration(
+      const cc::RenderFrameMetadata& metadata) {
+    return metadata.current_surface_visual_update_duration;
+  }
+
 #if BUILDFLAG(IS_ANDROID)
   static float bottom_controls_height(const cc::RenderFrameMetadata& metadata) {
     return metadata.bottom_controls_height;

cc/trees/commit_state.cc

@@ -38,7 +38,10 @@ CommitState::CommitState(const CommitState& prev)
       overscroll_behavior(prev.overscroll_behavior),
       background_color(prev.background_color),
       viewport_property_ids(prev.viewport_property_ids),
-      local_surface_id_from_parent(prev.local_surface_id_from_parent) {
+      local_surface_id_from_parent(prev.local_surface_id_from_parent),
+      previous_surfaces_visual_update_duration(
+          prev.previous_surfaces_visual_update_duration),
+      visual_update_duration(prev.visual_update_duration) {
   memcpy(event_listener_properties, prev.event_listener_properties,
          sizeof(event_listener_properties));
 }

cc/trees/commit_state.h

@@ -104,6 +104,8 @@ struct CC_EXPORT CommitState {
   SkColor background_color = SK_ColorWHITE;
   ViewportPropertyIds viewport_property_ids;
   viz::LocalSurfaceId local_surface_id_from_parent;
+  base::TimeDelta previous_surfaces_visual_update_duration;
+  base::TimeDelta visual_update_duration;
 
   // -------------------------------------------------------------------------
   // Take/reset: these values are reset on the LayerTreeHost between commits.

cc/trees/layer_tree_host.cc

@@ -409,6 +409,8 @@ std::unique_ptr<CommitState> LayerTreeHost::WillCommit(
   client_->WillCommit(has_updates ? *result : *pending_commit_state());
   pending_commit_state()->source_frame_number++;
   commit_completion_event_ = std::move(completion);
+  pending_commit_state()->previous_surfaces_visual_update_duration =
+      base::TimeDelta();
   return result;
 }
 
@@ -1517,6 +1519,13 @@ void LayerTreeHost::SetLocalSurfaceIdFromParent(
   pending_commit_state()->local_surface_id_from_parent =
       local_surface_id_from_parent;
 
+  // When we are switching to a new viz::LocalSurfaceId add our current visual
+  // update duration to that of previous surfaces, and clear out the total. So
+  // that we can begin to track the updates for this new Surface.
+  pending_commit_state()->previous_surfaces_visual_update_duration +=
+      pending_commit_state()->visual_update_duration;
+  pending_commit_state()->visual_update_duration = base::TimeDelta();
+
   // If the parent sequence number has not advanced, then there is no need to
   // commit anything. This can occur when the child sequence number has
   // advanced. Which means that child has changed visual properites, and the
@@ -1946,4 +1955,9 @@ uint32_t LayerTreeHost::GetAverageThroughput() const {
   return proxy_->GetAverageThroughput();
 }
 
+void LayerTreeHost::IncrementVisualUpdateDuration(
+    base::TimeDelta visual_update_duration) {
+  pending_commit_state()->visual_update_duration += visual_update_duration;
+}
+
 }  // namespace cc

cc/trees/layer_tree_host.h

@@ -851,6 +851,8 @@ class CC_EXPORT LayerTreeHost : public MutatorHostClient {
     return base::AutoReset<bool>(&syncing_deltas_for_test_, true);
   }
 
+  void IncrementVisualUpdateDuration(base::TimeDelta visual_update_duration);
+
  protected:
   LayerTreeHost(InitParams params, CompositorMode mode);
 

cc/trees/layer_tree_host_impl.cc

@@ -2432,6 +2432,14 @@ RenderFrameMetadata LayerTreeHostImpl::MakeRenderFrameMetadata(
         child_local_surface_id_allocator_.GetCurrentLocalSurfaceId();
   }
 
+  metadata.previous_surfaces_visual_update_duration =
+      active_tree()->previous_surfaces_visual_update_duration();
+  metadata.current_surface_visual_update_duration =
+      active_tree()->visual_update_duration();
+  // We only want to report the durations from a Commit the first time. Not for
+  // subsequent Impl-only frames.
+  active_tree()->ClearVisualUpdateDurations();
+
   return metadata;
 }
 

cc/trees/layer_tree_impl.cc

@@ -752,6 +752,10 @@ void LayerTreeImpl::PullLayerTreePropertiesFrom(CommitState& commit_state) {
   // Transfer page transition directives.
   for (auto& request : commit_state.document_transition_requests)
     AddDocumentTransitionRequest(std::move(request));
+
+  SetVisualUpdateDurations(
+      commit_state.previous_surfaces_visual_update_duration,
+      commit_state.visual_update_duration);
 }
 
 void LayerTreeImpl::PushPropertyTreesTo(LayerTreeImpl* target_tree) {
@@ -876,6 +880,9 @@ void LayerTreeImpl::PushPropertiesTo(LayerTreeImpl* target_tree) {
 
   for (auto& request : TakeDocumentTransitionRequests())
     target_tree->AddDocumentTransitionRequest(std::move(request));
+
+  target_tree->SetVisualUpdateDurations(
+      previous_surfaces_visual_update_duration_, visual_update_duration_);
 }
 
 void LayerTreeImpl::HandleTickmarksVisibilityChange() {
@@ -2888,4 +2895,17 @@ bool LayerTreeImpl::IsReadyToActivate() const {
   return host_impl_->IsReadyToActivate();
 }
 
+void LayerTreeImpl::ClearVisualUpdateDurations() {
+  previous_surfaces_visual_update_duration_ = base::TimeDelta();
+  visual_update_duration_ = base::TimeDelta();
+}
+
+void LayerTreeImpl::SetVisualUpdateDurations(
+    base::TimeDelta previous_surfaces_visual_update_duration,
+    base::TimeDelta visual_update_duration) {
+  previous_surfaces_visual_update_duration_ =
+      previous_surfaces_visual_update_duration;
+  visual_update_duration_ = visual_update_duration;
+}
+
 }  // namespace cc

cc/trees/layer_tree_impl.h

@@ -784,6 +784,17 @@ class CC_EXPORT LayerTreeImpl {
 
   bool HasDocumentTransitionRequests() const;
 
+  void ClearVisualUpdateDurations();
+  void SetVisualUpdateDurations(
+      base::TimeDelta previous_surfaces_visual_update_duration,
+      base::TimeDelta visual_update_duration);
+  base::TimeDelta previous_surfaces_visual_update_duration() const {
+    return previous_surfaces_visual_update_duration_;
+  }
+  base::TimeDelta visual_update_duration() const {
+    return visual_update_duration_;
+  }
+
  protected:
   float ClampPageScaleFactorToLimits(float page_scale_factor) const;
   void PushPageScaleFactorAndLimits(const float* page_scale_factor,
@@ -941,6 +952,13 @@ class CC_EXPORT LayerTreeImpl {
   // Document transition requests to be transferred to Viz.
   std::vector<std::unique_ptr<DocumentTransitionRequest>>
       document_transition_requests_;
+
+  // The cumulative time spent performing visual updates for all Surfaces before
+  // this one.
+  base::TimeDelta previous_surfaces_visual_update_duration_;
+  // The cumulative time spent performing visual updates for the current
+  // Surface.
+  base::TimeDelta visual_update_duration_;
 };
 
 }  // namespace cc

cc/trees/render_frame_metadata.cc

@@ -36,6 +36,10 @@ bool RenderFrameMetadata::operator==(const RenderFrameMetadata& other) const {
          external_page_scale_factor == other.external_page_scale_factor &&
          top_controls_height == other.top_controls_height &&
          top_controls_shown_ratio == other.top_controls_shown_ratio &&
+         previous_surfaces_visual_update_duration ==
+             other.previous_surfaces_visual_update_duration &&
+         current_surface_visual_update_duration ==
+             other.current_surface_visual_update_duration &&
 #if BUILDFLAG(IS_ANDROID)
          bottom_controls_height == other.bottom_controls_height &&
          bottom_controls_shown_ratio == other.bottom_controls_shown_ratio &&

cc/trees/render_frame_metadata.h

@@ -5,6 +5,7 @@
 #ifndef CC_TREES_RENDER_FRAME_METADATA_H_
 #define CC_TREES_RENDER_FRAME_METADATA_H_
 
+#include "base/time/time.h"
 #include "build/build_config.h"
 #include "cc/cc_export.h"
 #include "components/viz/common/quads/selection.h"
@@ -114,6 +115,14 @@ class CC_EXPORT RenderFrameMetadata {
   viz::VerticalScrollDirection new_vertical_scroll_direction =
       viz::VerticalScrollDirection::kNull;
 
+  // The cumulative time spent performing visual updates for all
+  // `local_surface_id` before this one.
+  base::TimeDelta previous_surfaces_visual_update_duration;
+
+  // The cumulative time spent performing visual updates for the current
+  // `local_surface_id`.
+  base::TimeDelta current_surface_visual_update_duration;
+
 #if BUILDFLAG(IS_ANDROID)
   // Used to position Android bottom bar, whose position is computed by the
   // renderer compositor.

content/browser/renderer_host/render_widget_host_impl.cc

@@ -3622,6 +3622,19 @@ void RenderWidgetHostImpl::OnRenderFrameMetadataChangedAfterActivation(
     base::TimeTicks activation_time) {
   const auto& metadata =
       render_frame_metadata_provider_.LastRenderFrameMetadata();
+  // We only want to report the timings for the very First Surface that is
+  // activated.
+  if (!first_surface_activated_) {
+    first_surface_activated_ = true;
+    UMA_HISTOGRAM_TIMES(
+        "Compositing.Renderer.FirstSurfaceActivationUpdateDuration."
+        "PreviousSurfaces",
+        metadata.previous_surfaces_visual_update_duration);
+    UMA_HISTOGRAM_TIMES(
+        "Compositing.Renderer.FirstSurfaceActivationUpdateDuration."
+        "CurrentSurface",
+        metadata.current_surface_visual_update_duration);
+  }
 
   bool is_mobile_optimized = metadata.is_mobile_optimized;
   input_router_->NotifySiteIsMobileOptimized(is_mobile_optimized);

content/browser/renderer_host/render_widget_host_impl.h

@@ -1444,6 +1444,11 @@ class CONTENT_EXPORT RenderWidgetHostImpl
   absl::optional<BrowserUIThreadScheduler::UserInputActiveHandle>
       user_input_active_handle_;
 
+  // Use for metrics reporting. Used to check if
+  // OnRenderFrameMetadataChangedAfterActivation is being called for the first
+  // time.
+  bool first_surface_activated_ = false;
+
   base::WeakPtrFactory<RenderWidgetHostImpl> weak_factory_{this};
 };
 

third_party/blink/renderer/platform/widget/widget_base.cc

@@ -9,6 +9,7 @@
 #include "base/metrics/histogram_macros.h"
 #include "base/ranges/algorithm.h"
 #include "base/threading/thread_task_runner_handle.h"
+#include "base/timer/elapsed_timer.h"
 #include "build/build_config.h"
 #include "cc/mojo_embedder/async_layer_tree_frame_sink.h"
 #include "cc/trees/layer_tree_host.h"
@@ -376,6 +377,7 @@ void WidgetBase::UpdateVisualProperties(
   //   See also:
   //   https://docs.google.com/document/d/1G_fR1D_0c1yke8CqDMddoKrDGr3gy5t_ImEH4hKNIII/edit#
 
+  base::ElapsedTimer update_timer;
   VisualProperties visual_properties = visual_properties_from_browser;
   auto& screen_info = visual_properties.screen_infos.mutable_current();
 
@@ -404,6 +406,8 @@ void WidgetBase::UpdateVisualProperties(
                              screen_info.device_scale_factor));
 
   client_->UpdateVisualProperties(visual_properties);
+
+  LayerTreeHost()->IncrementVisualUpdateDuration(update_timer.Elapsed());
 }
 
 void WidgetBase::UpdateScreenRects(const gfx::Rect& widget_screen_rect,
@@ -830,6 +834,7 @@ void WidgetBase::SetCompositorVisible(bool visible) {
 }
 
 void WidgetBase::UpdateVisualState() {
+  base::ElapsedTimer update_timer;
   // When recording main frame metrics set the lifecycle reason to
   // kBeginMainFrame, because this is the calller of UpdateLifecycle
   // for the main frame. Otherwise, set the reason to kTests, which is
@@ -840,6 +845,7 @@ void WidgetBase::UpdateVisualState() {
           : DocumentUpdateReason::kTest;
   client_->UpdateLifecycle(WebLifecycleUpdate::kAll, lifecycle_reason);
   client_->SetSuppressFrameRequestsWorkaroundFor704763Only(false);
+  LayerTreeHost()->IncrementVisualUpdateDuration(update_timer.Elapsed());
 }
 
 void WidgetBase::BeginMainFrame(base::TimeTicks frame_time) {

tools/metrics/histograms/metadata/compositing/histograms.xml

@@ -586,6 +586,31 @@ chromium-metrics-reviews@google.com.
   </summary>
 </histogram>
 
+<histogram
+    name="Compositing.Renderer.FirstSurfaceActivationUpdateDuration.{Surface}"
+    units="ms" expires_after="2023-04-28">
+  <owner>jonross@chromium.org</owner>
+  <owner>chrome-gpu-metrics@google.com</owner>
+  <summary>
+    The cumulative time spent performing visual updates for the {Surface}.
+
+    The time is measured in the Renderer. The result is reported in the Browser
+    when it is notified that the first Surface for a Renderer has been activated
+    by the GPU process. This is only reported for the first Surface that is
+    activated, and not for subsequent Surfaces.
+  </summary>
+  <token key="Surface">
+    <variant name="CurrentSurface"
+        summary="current surface which was activated. This time overlaps with
+                 when paint holding is deferring commits, and so is an upper
+                 bound"/>
+    <variant name="PreviousSurfaces"
+        summary="previous surfaces which were not activated. This time might
+                 overlap with when paint holding is deferring commits, and so
+                 is an upper bound"/>
+  </token>
+</histogram>
+
 <histogram name="Compositing.Renderer.GPUMemoryForTilingsInKb" units="Kb"
     expires_after="2022-11-09">
   <owner>pdr@chromium.org</owner>