Show Viz breakdowns as substages under PipelineReporter

This CL adds five substages, each corresponding to a Viz breakdown,
under the SubmitCompositorFrameToPresentationCompositorFrame stage of
the PipelineReporter in the trace viewer.

Bug: 1059032
Change-Id: I8473f69353ac21e9c63ccc093c504339d751d4ac
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2110771
Commit-Queue: Mingjing Zhang <mjzhang@chromium.org>
Reviewed-by: Behdad Bakhshinategh <behdadb@chromium.org>
Reviewed-by: Sadrul Chowdhury <sadrul@chromium.org>
Cr-Commit-Position: refs/heads/master@{#752551}

cc/metrics/compositor_frame_reporter.cc

@@ -41,6 +41,26 @@ constexpr int kBlinkBreakdownInitialIndex =
 constexpr int kFrameSequenceTrackerTypeCount =
     static_cast<int>(FrameSequenceTrackerType::kMaxType) + 1;
 
+// Names for the viz breakdowns that are shown in trace as substages under
+// PipelineReporter -> SubmitCompositorFrameToPresentationCompositorFrame
+constexpr const char* GetVizBreakdownName(VizBreakdown stage) {
+  switch (stage) {
+    case VizBreakdown::kSubmitToReceiveCompositorFrame:
+      return "SubmitToReceiveCompositorFrame";
+    case VizBreakdown::kReceivedCompositorFrameToStartDraw:
+      return "ReceiveCompositorFrameToStartDraw";
+    case VizBreakdown::kStartDrawToSwapStart:
+      return "StartDrawToSwapStart";
+    case VizBreakdown::kSwapStartToSwapEnd:
+      return "Swap";
+    case VizBreakdown::kSwapEndToPresentationCompositorFrame:
+      return "SwapEndToPresentationCompositorFrame";
+    case VizBreakdown::kBreakdownCount:
+      NOTREACHED();
+      return "";
+  }
+}
+
 // Names for CompositorFrameReporter::StageType, which should be updated in case
 // of changes to the enum.
 constexpr const char* GetStageName(int stage_type_index) {
@@ -416,6 +436,19 @@ void CompositorFrameReporter::ReportBlinkBreakdowns(
   }
 }
 
+void CompositorFrameReporter::ReportVizBreakdownStage(
+    VizBreakdown stage,
+    const base::TimeTicks start_time,
+    const base::TimeTicks end_time,
+    FrameSequenceTrackerType frame_sequence_tracker_type) const {
+  base::TimeDelta time_delta = end_time - start_time;
+
+  ReportVizBreakdownTrace(stage, start_time, end_time);
+  ReportCompositorLatencyHistogram(
+      frame_sequence_tracker_type,
+      kVizBreakdownInitialIndex + static_cast<int>(stage), time_delta);
+}
+
 void CompositorFrameReporter::ReportVizBreakdowns(
     base::TimeTicks start_time,
     FrameSequenceTrackerType frame_sequence_tracker_type) const {
@@ -426,56 +459,32 @@ void CompositorFrameReporter::ReportVizBreakdowns(
       viz_breakdown_.received_compositor_frame_timestamp < start_time) {
     return;
   }
-  base::TimeDelta submit_to_receive_compositor_frame_delta =
-      viz_breakdown_.received_compositor_frame_timestamp - start_time;
-  ReportCompositorLatencyHistogram(
-      frame_sequence_tracker_type,
-      kVizBreakdownInitialIndex +
-          static_cast<int>(VizBreakdown::kSubmitToReceiveCompositorFrame),
-      submit_to_receive_compositor_frame_delta);
+  ReportVizBreakdownStage(VizBreakdown::kSubmitToReceiveCompositorFrame,
+                          start_time,
+                          viz_breakdown_.received_compositor_frame_timestamp,
+                          frame_sequence_tracker_type);
 
   if (viz_breakdown_.draw_start_timestamp.is_null())
     return;
-  base::TimeDelta received_compositor_frame_to_start_draw_delta =
-      viz_breakdown_.draw_start_timestamp -
-      viz_breakdown_.received_compositor_frame_timestamp;
-  ReportCompositorLatencyHistogram(
-      frame_sequence_tracker_type,
-      kVizBreakdownInitialIndex +
-          static_cast<int>(VizBreakdown::kReceivedCompositorFrameToStartDraw),
-      received_compositor_frame_to_start_draw_delta);
+  ReportVizBreakdownStage(VizBreakdown::kReceivedCompositorFrameToStartDraw,
+                          viz_breakdown_.received_compositor_frame_timestamp,
+                          viz_breakdown_.draw_start_timestamp,
+                          frame_sequence_tracker_type);
 
   if (viz_breakdown_.swap_timings.is_null())
     return;
-  base::TimeDelta start_draw_to_swap_start_delta =
-      viz_breakdown_.swap_timings.swap_start -
-      viz_breakdown_.draw_start_timestamp;
-
-  ReportCompositorLatencyHistogram(
-      frame_sequence_tracker_type,
-      kVizBreakdownInitialIndex +
-          static_cast<int>(VizBreakdown::kStartDrawToSwapStart),
-      start_draw_to_swap_start_delta);
-
-  base::TimeDelta swap_start_to_swap_end_delta =
-      viz_breakdown_.swap_timings.swap_end -
-      viz_breakdown_.swap_timings.swap_start;
-
-  ReportCompositorLatencyHistogram(
-      frame_sequence_tracker_type,
-      kVizBreakdownInitialIndex +
-          static_cast<int>(VizBreakdown::kSwapStartToSwapEnd),
-      swap_start_to_swap_end_delta);
-
-  base::TimeDelta swap_end_to_presentation_compositor_frame_delta =
-      viz_breakdown_.presentation_feedback.timestamp -
-      viz_breakdown_.swap_timings.swap_end;
-
-  ReportCompositorLatencyHistogram(
-      frame_sequence_tracker_type,
-      kVizBreakdownInitialIndex +
-          static_cast<int>(VizBreakdown::kSwapEndToPresentationCompositorFrame),
-      swap_end_to_presentation_compositor_frame_delta);
+  ReportVizBreakdownStage(
+      VizBreakdown::kStartDrawToSwapStart, viz_breakdown_.draw_start_timestamp,
+      viz_breakdown_.swap_timings.swap_start, frame_sequence_tracker_type);
+
+  ReportVizBreakdownStage(
+      VizBreakdown::kSwapStartToSwapEnd, viz_breakdown_.swap_timings.swap_start,
+      viz_breakdown_.swap_timings.swap_end, frame_sequence_tracker_type);
+
+  ReportVizBreakdownStage(VizBreakdown::kSwapEndToPresentationCompositorFrame,
+                          viz_breakdown_.swap_timings.swap_end,
+                          viz_breakdown_.presentation_feedback.timestamp,
+                          frame_sequence_tracker_type);
 }
 
 void CompositorFrameReporter::ReportCompositorLatencyHistogram(
@@ -573,6 +582,22 @@ void CompositorFrameReporter::ReportEventLatencyHistograms() const {
   }
 }
 
+void CompositorFrameReporter::ReportVizBreakdownTrace(
+    VizBreakdown substage,
+    const base::TimeTicks start_time,
+    const base::TimeTicks end_time) const {
+  // Do not report events with negative time span.
+  if (end_time < start_time)
+    return;
+
+  const char* stage_name = GetVizBreakdownName(substage);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
+      "cc,benchmark", stage_name, TRACE_ID_LOCAL(this), start_time);
+
+  TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
+      "cc,benchmark", stage_name, TRACE_ID_LOCAL(this), end_time);
+}
+
 base::TimeDelta CompositorFrameReporter::SumOfStageHistory() const {
   base::TimeDelta sum;
   for (const StageData& stage : stage_history_)

cc/metrics/compositor_frame_reporter.h

@@ -164,6 +164,14 @@ class CC_EXPORT CompositorFrameReporter {
   void ReportBlinkBreakdowns(
       const base::TimeTicks start_time,
       FrameSequenceTrackerType frame_sequence_tracker_type) const;
+
+  // Report histogram and trace event stage for one Viz breakdown
+  void ReportVizBreakdownStage(
+      VizBreakdown stage,
+      const base::TimeTicks start_time,
+      const base::TimeTicks end_time,
+      FrameSequenceTrackerType frame_sequence_tracker_type) const;
+
   void ReportVizBreakdowns(
       const base::TimeTicks start_time,
       FrameSequenceTrackerType frame_sequence_tracker_type) const;
@@ -173,6 +181,14 @@ class CC_EXPORT CompositorFrameReporter {
       base::TimeDelta time_delta) const;
   void ReportEventLatencyHistograms() const;
 
+  // Generate a trace event corresponding to a Viz breakdown under
+  // SubmitCompositorFrameToPresentationCompositorFrame stage in
+  // PipelineReporter. This function only generates trace events and does not
+  // report histograms.
+  void ReportVizBreakdownTrace(VizBreakdown substage,
+                               const base::TimeTicks start_time,
+                               const base::TimeTicks end_time) const;
+
   StageData current_stage_;
   BeginMainFrameMetrics blink_breakdown_;
   viz::FrameTimingDetails viz_breakdown_;