Added trace events for surface synchronization and embedding

Added some trace events in the viz.surface_id_flow category to trace surface id synchronization until Surface::OnWillBeDrawn is called on the surface.

Bug: 933503
Change-Id: I7c51af6bc8cab90c4ff6b91341e2625d1bb67b0b
Reviewed-on: https://chromium-review.googlesource.com/c/1478934Reviewed-by: Jonathan Ross <jonross@chromium.org>
Reviewed-by: Saman Sami <samans@chromium.org>
Reviewed-by: Ken Buchanan <kenrb@chromium.org>
Commit-Queue: Edwin Joe <ejoe@google.com>
Cr-Commit-Position: refs/heads/master@{#634757}

cc/mojo_embedder/async_layer_tree_frame_sink.cc

@@ -245,12 +245,22 @@ void AsyncLayerTreeFrameSink::SubmitCompositorFrame(
     last_submitted_device_scale_factor_ = frame.device_scale_factor();
     last_submitted_size_in_pixels_ = frame.size_in_pixels();
 
+    // These traces are split into two due to the incoming flow using
+    // TRACE_ID_LOCAL, and the outgoing flow using TRACE_ID_GLOBAL. This is
+    // needed to ensure the incoming flow is not messed up. The outgoing flow is
+    // going to a different process.
+    TRACE_EVENT_WITH_FLOW2(
+        TRACE_DISABLED_BY_DEFAULT("viz.surface_id_flow"),
+        "LocalSurfaceId.Submission.Flow",
+        TRACE_ID_LOCAL(local_surface_id_.submission_trace_id()),
+        TRACE_EVENT_FLAG_FLOW_IN, "step", "SubmitCompositorFrame", "surface_id",
+        local_surface_id_.ToString());
     TRACE_EVENT_WITH_FLOW2(
         TRACE_DISABLED_BY_DEFAULT("viz.surface_id_flow"),
         "LocalSurfaceId.Submission.Flow",
         TRACE_ID_GLOBAL(local_surface_id_.submission_trace_id()),
-        TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT, "step",
-        "SubmitCompositorFrame", "surface_id", local_surface_id_.ToString());
+        TRACE_EVENT_FLAG_FLOW_OUT, "step", "SubmitCompositorFrame",
+        "surface_id", local_surface_id_.ToString());
   }
 
   // The trace_id is negated in order to keep the Graphics.Pipeline and

cc/trees/layer_tree_host.cc

@@ -1342,11 +1342,22 @@ void LayerTreeHost::SetLocalSurfaceIdAllocationFromParent(
   DCHECK_EQ(local_surface_id_from_parent.is_valid(),
             local_surface_id_allocation_from_parent.IsValid());
 
+  // These traces are split into two due to the usage of TRACE_ID_GLOBAL for the
+  // incoming flow (it comes from a different process), and TRACE_ID_LOCAL for
+  // the outgoing flow. The outgoing flow uses local to ensure that it doesn't
+  // flow into the wrong trace in different process.
   TRACE_EVENT_WITH_FLOW2(
       TRACE_DISABLED_BY_DEFAULT("viz.surface_id_flow"),
       "LocalSurfaceId.Submission.Flow",
       TRACE_ID_GLOBAL(local_surface_id_from_parent.submission_trace_id()),
-      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT, "step",
+      TRACE_EVENT_FLAG_FLOW_IN, "step", "SetLocalSurfaceAllocationIdFromParent",
+      "local_surface_id_allocation",
+      local_surface_id_allocation_from_parent.ToString());
+  TRACE_EVENT_WITH_FLOW2(
+      TRACE_DISABLED_BY_DEFAULT("viz.surface_id_flow"),
+      "LocalSurfaceId.Submission.Flow",
+      TRACE_ID_LOCAL(local_surface_id_from_parent.submission_trace_id()),
+      TRACE_EVENT_FLAG_FLOW_OUT, "step",
       "SetLocalSurfaceAllocationIdFromParent", "local_surface_id_allocation",
       local_surface_id_allocation_from_parent.ToString());
   // Always update the cached state of the viz::LocalSurfaceId to reflect the

components/viz/common/surfaces/child_local_surface_id_allocator.cc

@@ -53,9 +53,29 @@ bool ChildLocalSurfaceIdAllocator::UpdateFromParent(
     // than the one provided by the parent, then the merged LocalSurfaceId
     // is actually a new LocalSurfaceId and so we report its allocation time
     // as now.
+    if (current_local_surface_id != parent_allocated_local_surface_id) {
+      TRACE_EVENT_WITH_FLOW2(
+          TRACE_DISABLED_BY_DEFAULT("viz.surface_id_flow"),
+          "ChildLocalSurfaceIdAllocator::UpdateFromParent New Id Allocation",
+          TRACE_ID_LOCAL(
+              parent_allocated_local_surface_id.submission_trace_id()),
+          TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT, "current",
+          current_local_surface_id_allocation_.ToString(), "parent",
+          parent_local_surface_id_allocation.ToString());
+    }
     current_local_surface_id_allocation_.allocation_time_ =
         tick_clock_->NowTicks();
   } else {
+    if (current_local_surface_id != parent_allocated_local_surface_id) {
+      TRACE_EVENT_WITH_FLOW2(
+          TRACE_DISABLED_BY_DEFAULT("viz.surface_id_flow"),
+          "ChildLocalSurfaceIdAllocator::UpdateFromParent Synchronization",
+          TRACE_ID_LOCAL(
+              parent_allocated_local_surface_id.submission_trace_id()),
+          TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT, "current",
+          current_local_surface_id_allocation_.ToString(), "parent",
+          parent_local_surface_id_allocation.ToString());
+    }
     current_local_surface_id_allocation_.allocation_time_ =
         parent_local_surface_id_allocation.allocation_time();
   }

components/viz/common/surfaces/parent_local_surface_id_allocator.cc

@@ -45,9 +45,19 @@ bool ParentLocalSurfaceIdAllocator::UpdateFromChild(
     // than the one provided by the child, then the merged LocalSurfaceId
     // is actually a new LocalSurfaceId and so we report its allocation time
     // as now.
+    TRACE_EVENT2(
+        TRACE_DISABLED_BY_DEFAULT("viz.surface_id_flow"),
+        "ParentLocalSurfaceIdAllocator::UpdateFromChild New Allocation",
+        "current", current_local_surface_id_allocation_.ToString(), "child",
+        child_local_surface_id_allocation.ToString());
     current_local_surface_id_allocation_.allocation_time_ =
         tick_clock_->NowTicks();
   } else {
+    TRACE_EVENT2(
+        TRACE_DISABLED_BY_DEFAULT("viz.surface_id_flow"),
+        "ParentLocalSurfaceIdAllocator::UpdateFromChild Synchronization",
+        "current", current_local_surface_id_allocation_.ToString(), "child",
+        child_local_surface_id_allocation.ToString());
     current_local_surface_id_allocation_.allocation_time_ =
         child_local_surface_id_allocation.allocation_time();
   }

content/browser/frame_host/cross_process_frame_connector.cc

@@ -333,6 +333,17 @@ void CrossProcessFrameConnector::UnlockMouse() {
 void CrossProcessFrameConnector::OnSynchronizeVisualProperties(
     const viz::FrameSinkId& frame_sink_id,
     const FrameVisualProperties& visual_properties) {
+  TRACE_EVENT_WITH_FLOW2(
+      TRACE_DISABLED_BY_DEFAULT("viz.surface_id_flow"),
+      "CrossProcessFrameConnector::OnSynchronizeVisualProperties Receive "
+      "Message",
+      TRACE_ID_GLOBAL(
+          visual_properties.local_surface_id_allocation.local_surface_id()
+              .submission_trace_id()),
+      TRACE_EVENT_FLAG_FLOW_IN, "message",
+      "FrameHostMsg_SynchronizeVisualProperties", "new_local_surface_id",
+      visual_properties.local_surface_id_allocation.local_surface_id()
+          .ToString());
   // If the |screen_space_rect| or |screen_info| of the frame has changed, then
   // the viz::LocalSurfaceId must also change.
   if ((last_received_local_frame_size_ != visual_properties.local_frame_size ||

content/browser/renderer_host/render_widget_host_impl.cc

@@ -1066,6 +1066,15 @@ bool RenderWidgetHostImpl::SynchronizeVisualProperties(
   bool sent_visual_properties = false;
   if (Send(new WidgetMsg_SynchronizeVisualProperties(routing_id_,
                                                      *visual_properties))) {
+    TRACE_EVENT_WITH_FLOW2(
+        TRACE_DISABLED_BY_DEFAULT("viz.surface_id_flow"),
+        "RenderWidgetHostImpl::SynchronizeVisualProperties send message",
+        visual_properties->local_surface_id_allocation->local_surface_id()
+            .submission_trace_id(),
+        TRACE_EVENT_FLAG_FLOW_OUT, "message",
+        "WidgetMsg_SynchronizeVisualProperties", "local_surface_id",
+        visual_properties->local_surface_id_allocation->local_surface_id()
+            .ToString());
     visual_properties_ack_pending_ = needs_ack;
     old_visual_properties_.swap(visual_properties);
     sent_visual_properties = true;
@@ -2384,8 +2393,20 @@ void RenderWidgetHostImpl::DidDeleteSharedBitmap(
 
 void RenderWidgetHostImpl::DidUpdateVisualProperties(
     const cc::RenderFrameMetadata& metadata) {
-  TRACE_EVENT0("renderer_host",
-               "RenderWidgetHostImpl::DidUpdateVisualProperties");
+  TRACE_EVENT_WITH_FLOW1(
+      "renderer_host,disabled-by-default-viz.surface_id_flow",
+      "RenderWidgetHostImpl::DidUpdateVisualProperties",
+      metadata.local_surface_id_allocation &&
+              metadata.local_surface_id_allocation->IsValid()
+          ? metadata.local_surface_id_allocation->local_surface_id()
+                    .submission_trace_id() +
+                metadata.local_surface_id_allocation->local_surface_id()
+                    .embed_trace_id()
+          : 0,
+      TRACE_EVENT_FLAG_FLOW_IN, "local_surface_id_allocation",
+      metadata.local_surface_id_allocation
+          ? metadata.local_surface_id_allocation->ToString()
+          : "null");
 
   // Update our knowledge of the RenderWidget's size.
   DCHECK(!metadata.viewport_size_in_pixels.IsEmpty());

content/renderer/render_frame_metadata_observer_impl.cc

@@ -81,6 +81,21 @@ void RenderFrameMetadataObserverImpl::OnRenderFrameSubmission(
         needs_activation_notification;
     render_frame_metadata_observer_client_->OnRenderFrameMetadataChanged(
         needs_activation_notification ? last_frame_token_ : 0u, metadata_copy);
+    TRACE_EVENT_WITH_FLOW1(
+        TRACE_DISABLED_BY_DEFAULT("viz.surface_id_flow"),
+        "RenderFrameMetadataObserverImpl::OnRenderFrameSubmission",
+        metadata_copy.local_surface_id_allocation &&
+                metadata_copy.local_surface_id_allocation->IsValid()
+            ? metadata_copy.local_surface_id_allocation->local_surface_id()
+                      .submission_trace_id() +
+                  metadata_copy.local_surface_id_allocation->local_surface_id()
+                      .embed_trace_id()
+            : 0,
+        TRACE_EVENT_FLAG_FLOW_OUT, "local_surface_id_allocation",
+        metadata_copy.local_surface_id_allocation
+            ? metadata_copy.local_surface_id_allocation->local_surface_id()
+                  .ToString()
+            : "null");
   }
 
   // Always cache the initial frame token, so that if a test connects later on

content/renderer/render_frame_proxy.cc

@@ -709,6 +709,17 @@ void RenderFrameProxy::SynchronizeVisualProperties() {
       routing_id_, frame_sink_id_, pending_visual_properties_));
   sent_visual_properties_ = pending_visual_properties_;
 
+  TRACE_EVENT_WITH_FLOW2(
+      TRACE_DISABLED_BY_DEFAULT("viz.surface_id_flow"),
+      "RenderFrameProxy::SynchronizeVisualProperties Send Message",
+      TRACE_ID_GLOBAL(pending_visual_properties_.local_surface_id_allocation
+                          .local_surface_id()
+                          .submission_trace_id()),
+      TRACE_EVENT_FLAG_FLOW_OUT, "message",
+      "FrameHostMsg_SynchronizeVisualProperties", "local_surface_id",
+      pending_visual_properties_.local_surface_id_allocation.local_surface_id()
+          .ToString());
+
   // The visible rect that the OOPIF needs to raster depends partially on
   // parameters that might have changed. If they affect the raster area, resend
   // the intersection rects.