Add compositor breakdowns to EventLatency metrics

Currently, EventLatency metrics only measure total latency from event
timestamp up to frame presentation (and for scroll events, from event
timestamp up to gpu-swap-end). This CL adds top-level compositor
breakdowns. Further breakdowns for blink and viz stages will be added in
follow-up CLs.

Bug: 1054009
Change-Id: I65341dbc10d08b8acbd05185cf270b0a1fc4d842
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2132853Reviewed-by: Jonathan Ross <jonross@chromium.org>
Reviewed-by: Behdad Bakhshinategh <behdadb@chromium.org>
Reviewed-by: Sadrul Chowdhury <sadrul@chromium.org>
Commit-Queue: Mohsen Izadi <mohsen@chromium.org>
Cr-Commit-Position: refs/heads/master@{#756280}

cc/metrics/compositor_frame_reporter.cc

@@ -160,8 +160,10 @@ constexpr int kEventLatencyEventTypeCount =
     static_cast<int>(ui::EventType::ET_LAST);
 constexpr int kEventLatencyScrollTypeCount =
     static_cast<int>(ScrollInputType::kMaxValue) + 1;
-constexpr int kMaxEventLatencyHistogramIndex =
+constexpr int kMaxEventLatencyHistogramBaseIndex =
     kEventLatencyEventTypeCount * kEventLatencyScrollTypeCount;
+constexpr int kMaxEventLatencyHistogramIndex =
+    kMaxEventLatencyHistogramBaseIndex * kStageTypeCount;
 constexpr int kEventLatencyHistogramMin = 1;
 constexpr int kEventLatencyHistogramMax = 5000000;
 constexpr int kEventLatencyHistogramBucketCount = 100;
@@ -543,7 +545,7 @@ void CompositorFrameReporter::ReportEventLatencyHistograms() const {
         event_metrics.scroll_input_type()
             ? static_cast<int>(*event_metrics.scroll_input_type())
             : 0;
-    const int histogram_index =
+    const int histogram_base_index =
         event_type_index * kEventLatencyScrollTypeCount + scroll_type_index;
 
     // For scroll events, report total latency up to gpu-swap-end. This is
@@ -556,8 +558,8 @@ void CompositorFrameReporter::ReportEventLatencyHistograms() const {
       const std::string swap_end_histogram_name =
           histogram_base_name + ".TotalLatencyToSwapEnd";
       STATIC_HISTOGRAM_POINTER_GROUP(
-          swap_end_histogram_name, histogram_index,
-          kMaxEventLatencyHistogramIndex,
+          swap_end_histogram_name, histogram_base_index,
+          kMaxEventLatencyHistogramBaseIndex,
           AddTimeMicrosecondsGranularity(swap_end_latency),
           base::Histogram::FactoryGet(
               swap_end_histogram_name, kEventLatencyHistogramMin,
@@ -565,53 +567,72 @@ void CompositorFrameReporter::ReportEventLatencyHistograms() const {
               base::HistogramBase::kUmaTargetedHistogramFlag));
     }
 
-    base::TimeDelta total_latency =
-        frame_termination_time_ - event_metrics.time_stamp();
-    const std::string histogram_name = histogram_base_name + ".TotalLatency";
-    STATIC_HISTOGRAM_POINTER_GROUP(
-        histogram_name, histogram_index, kMaxEventLatencyHistogramIndex,
-        AddTimeMicrosecondsGranularity(total_latency),
-        base::Histogram::FactoryGet(
-            histogram_name, kEventLatencyHistogramMin,
-            kEventLatencyHistogramMax, kEventLatencyHistogramBucketCount,
-            base::HistogramBase::kUmaTargetedHistogramFlag));
-
     const auto trace_id = TRACE_ID_LOCAL(&event_metrics);
     TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP1(
         "cc,input", "EventLatency", trace_id, event_metrics.time_stamp(),
         "event", event_metrics.GetTypeName());
 
-    // Report the breakdowns.
     // It is possible for an event to arrive in the compositor in the middle of
     // a frame (e.g. the browser received the event *after* renderer received a
     // begin-impl, and the event reached the compositor before that frame
     // ended). To handle such cases, find the first stage that happens after the
     // event's arrival in the browser.
-    // TODO(mohsen): Report the breakdowns in UMA too.
     size_t index = 0;
     for (; index < stage_history_.size(); ++index) {
       const auto& stage = stage_history_[index];
       if (stage.start_time > event_metrics.time_stamp()) {
+        const char stage_type_name[] = "BrowserToRendererCompositor";
+
+        const base::TimeDelta latency =
+            stage.start_time - event_metrics.time_stamp();
+        const std::string histogram_name =
+            base::StrCat({histogram_base_name, ".", stage_type_name});
+        STATIC_HISTOGRAM_POINTER_GROUP(
+            histogram_name, histogram_base_index,
+            kMaxEventLatencyHistogramBaseIndex,
+            AddTimeMicrosecondsGranularity(latency),
+            base::Histogram::FactoryGet(
+                histogram_name, kEventLatencyHistogramMin,
+                kEventLatencyHistogramMax, kEventLatencyHistogramBucketCount,
+                base::HistogramBase::kUmaTargetedHistogramFlag));
+
         TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
-            "cc,input", "BrowserToRendererCompositor", trace_id,
-            event_metrics.time_stamp());
+            "cc,input", stage_type_name, trace_id, event_metrics.time_stamp());
         TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
-            "cc,input", "BrowserToRendererCompositor", trace_id,
-            stage.start_time);
+            "cc,input", stage_type_name, trace_id, stage.start_time);
         break;
       }
     }
 
     for (; index < stage_history_.size(); ++index) {
       const auto& stage = stage_history_[index];
-      if (stage.stage_type == StageType::kTotalLatency)
-        break;
-      TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
-          "cc,input", GetStageName(static_cast<int>(stage.stage_type)),
-          trace_id, stage.start_time);
-      TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
-          "cc,input", GetStageName(static_cast<int>(stage.stage_type)),
-          trace_id, stage.end_time);
+
+      // Total latency is calculated since the event timestamp.
+      const base::TimeTicks start_time =
+          stage.stage_type == StageType::kTotalLatency
+              ? event_metrics.time_stamp()
+              : stage.start_time;
+      const base::TimeDelta latency = stage.end_time - start_time;
+      const int stage_type_index = static_cast<int>(stage.stage_type);
+      const char* stage_type_name = GetStageName(stage_type_index);
+      const std::string histogram_name =
+          base::StrCat({histogram_base_name, ".", stage_type_name});
+      const int histogram_index =
+          histogram_base_index * kStageTypeCount + stage_type_index;
+      STATIC_HISTOGRAM_POINTER_GROUP(
+          histogram_name, histogram_index, kMaxEventLatencyHistogramIndex,
+          AddTimeMicrosecondsGranularity(latency),
+          base::Histogram::FactoryGet(
+              histogram_name, kEventLatencyHistogramMin,
+              kEventLatencyHistogramMax, kEventLatencyHistogramBucketCount,
+              base::HistogramBase::kUmaTargetedHistogramFlag));
+
+      if (stage.stage_type != StageType::kTotalLatency) {
+        TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
+            "cc,input", stage_type_name, trace_id, stage.start_time);
+        TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
+            "cc,input", stage_type_name, trace_id, stage.end_time);
+      }
     }
     TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
         "cc,input", "EventLatency", trace_id, frame_termination_time_);

cc/metrics/compositor_frame_reporter_unittest.cc

@@ -39,24 +39,21 @@ class CompositorFrameReporterTest : public testing::Test {
   }
 
  protected:
-  void AdvanceNowByMs(int advance_ms) {
+  base::TimeTicks AdvanceNowByMs(int advance_ms) {
     now_ += base::TimeDelta::FromMicroseconds(advance_ms);
+    return now_;
   }
 
   base::TimeTicks Now() { return now_; }
 
   viz::FrameTimingDetails BuildFrameTimingDetails() {
     viz::FrameTimingDetails frame_timing_details;
-    AdvanceNowByMs(1);
-    frame_timing_details.received_compositor_frame_timestamp = Now();
-    AdvanceNowByMs(1);
-    frame_timing_details.draw_start_timestamp = Now();
-    AdvanceNowByMs(1);
-    frame_timing_details.swap_timings.swap_start = Now();
-    AdvanceNowByMs(1);
-    frame_timing_details.swap_timings.swap_end = Now();
-    AdvanceNowByMs(1);
-    frame_timing_details.presentation_feedback.timestamp = Now();
+    frame_timing_details.received_compositor_frame_timestamp =
+        AdvanceNowByMs(1);
+    frame_timing_details.draw_start_timestamp = AdvanceNowByMs(1);
+    frame_timing_details.swap_timings.swap_start = AdvanceNowByMs(1);
+    frame_timing_details.swap_timings.swap_end = AdvanceNowByMs(1);
+    frame_timing_details.presentation_feedback.timestamp = AdvanceNowByMs(1);
     return frame_timing_details;
   }
 
@@ -257,6 +254,116 @@ TEST_F(CompositorFrameReporterTest, EventLatencyForPresentedFrameReported) {
                                      latency_ms, 2);
 }
 
+// Tests that when a frame is presented to the user, event latency breakdown
+// metrics are reported properly.
+TEST_F(CompositorFrameReporterTest,
+       EventLatencyBreakdownsForPresentedFrameReported) {
+  base::HistogramTester histogram_tester;
+
+  const base::TimeTicks event_time = Now();
+  std::vector<EventMetrics> events_metrics = {
+      {ui::ET_TOUCH_PRESSED, event_time, base::nullopt},
+      {ui::ET_TOUCH_MOVED, event_time, base::nullopt},
+      {ui::ET_TOUCH_MOVED, event_time, base::nullopt},
+  };
+  EXPECT_THAT(events_metrics, ::testing::Each(IsWhitelisted()));
+
+  auto begin_impl_time = AdvanceNowByMs(2);
+  pipeline_reporter_->StartStage(
+      CompositorFrameReporter::StageType::kBeginImplFrameToSendBeginMainFrame,
+      begin_impl_time);
+
+  auto begin_main_time = AdvanceNowByMs(3);
+  pipeline_reporter_->StartStage(
+      CompositorFrameReporter::StageType::kSendBeginMainFrameToCommit,
+      begin_main_time);
+
+  auto begin_commit_time = AdvanceNowByMs(4);
+  pipeline_reporter_->StartStage(CompositorFrameReporter::StageType::kCommit,
+                                 begin_commit_time);
+
+  auto end_commit_time = AdvanceNowByMs(5);
+  pipeline_reporter_->StartStage(
+      CompositorFrameReporter::StageType::kEndCommitToActivation,
+      end_commit_time);
+
+  auto begin_activation_time = AdvanceNowByMs(6);
+  pipeline_reporter_->StartStage(
+      CompositorFrameReporter::StageType::kActivation, begin_activation_time);
+
+  auto end_activation_time = AdvanceNowByMs(7);
+  pipeline_reporter_->StartStage(
+      CompositorFrameReporter::StageType::kEndActivateToSubmitCompositorFrame,
+      end_activation_time);
+
+  auto submit_time = AdvanceNowByMs(8);
+  pipeline_reporter_->StartStage(
+      CompositorFrameReporter::StageType::
+          kSubmitCompositorFrameToPresentationCompositorFrame,
+      submit_time);
+  pipeline_reporter_->SetEventsMetrics(std::move(events_metrics));
+
+  auto presentation_time = AdvanceNowByMs(9);
+  pipeline_reporter_->TerminateFrame(
+      CompositorFrameReporter::FrameTerminationStatus::kPresentedFrame,
+      presentation_time);
+
+  pipeline_reporter_ = nullptr;
+
+  struct {
+    const char* name;
+    const base::TimeDelta latency;
+    const int count;
+  } expected_counts[] = {
+      {"EventLatency.TouchPressed.BrowserToRendererCompositor",
+       begin_impl_time - event_time, 1},
+      {"EventLatency.TouchPressed.BeginImplFrameToSendBeginMainFrame",
+       begin_main_time - begin_impl_time, 1},
+      {"EventLatency.TouchPressed.SendBeginMainFrameToCommit",
+       begin_commit_time - begin_main_time, 1},
+      {"EventLatency.TouchPressed.Commit", end_commit_time - begin_commit_time,
+       1},
+      {"EventLatency.TouchPressed.EndCommitToActivation",
+       begin_activation_time - end_commit_time, 1},
+      {"EventLatency.TouchPressed.Activation",
+       end_activation_time - begin_activation_time, 1},
+      {"EventLatency.TouchPressed.EndActivateToSubmitCompositorFrame",
+       submit_time - end_activation_time, 1},
+      {"EventLatency.TouchPressed."
+       "SubmitCompositorFrameToPresentationCompositorFrame",
+       presentation_time - submit_time, 1},
+      {"EventLatency.TouchPressed.TotalLatency", presentation_time - event_time,
+       1},
+      {"EventLatency.TouchMoved.BrowserToRendererCompositor",
+       begin_impl_time - event_time, 2},
+      {"EventLatency.TouchMoved.BeginImplFrameToSendBeginMainFrame",
+       begin_main_time - begin_impl_time, 2},
+      {"EventLatency.TouchMoved.SendBeginMainFrameToCommit",
+       begin_commit_time - begin_main_time, 2},
+      {"EventLatency.TouchMoved.Commit", end_commit_time - begin_commit_time,
+       2},
+      {"EventLatency.TouchMoved.EndCommitToActivation",
+       begin_activation_time - end_commit_time, 2},
+      {"EventLatency.TouchMoved.Activation",
+       end_activation_time - begin_activation_time, 2},
+      {"EventLatency.TouchMoved.EndActivateToSubmitCompositorFrame",
+       submit_time - end_activation_time, 2},
+      {"EventLatency.TouchMoved."
+       "SubmitCompositorFrameToPresentationCompositorFrame",
+       presentation_time - submit_time, 2},
+      {"EventLatency.TouchMoved.TotalLatency", presentation_time - event_time,
+       2},
+  };
+
+  for (const auto& expected_count : expected_counts) {
+    histogram_tester.ExpectTotalCount(expected_count.name,
+                                      expected_count.count);
+    histogram_tester.ExpectBucketCount(expected_count.name,
+                                       expected_count.latency.InMicroseconds(),
+                                       expected_count.count);
+  }
+}
+
 // Tests that when a frame is presented to the user, scroll event latency
 // metrics are reported properly.
 TEST_F(CompositorFrameReporterTest,

content/browser/renderer_host/input/event_latency_aura_browsertest.cc

@@ -83,6 +83,16 @@ IN_PROC_BROWSER_TEST_F(EventLatencyBrowserTest, KeyPressOnButton) {
   FetchHistogramsFromChildProcesses();
 
   base::HistogramTester::CountsMap expected_counts = {
+      {"EventLatency.KeyReleased.BrowserToRendererCompositor", 1},
+      {"EventLatency.KeyReleased.BeginImplFrameToSendBeginMainFrame", 1},
+      {"EventLatency.KeyReleased.SendBeginMainFrameToCommit", 1},
+      {"EventLatency.KeyReleased.Commit", 1},
+      {"EventLatency.KeyReleased.EndCommitToActivation", 1},
+      {"EventLatency.KeyReleased.Activation", 1},
+      {"EventLatency.KeyReleased.EndActivateToSubmitCompositorFrame", 1},
+      {"EventLatency.KeyReleased."
+       "SubmitCompositorFrameToPresentationCompositorFrame",
+       1},
       {"EventLatency.KeyReleased.TotalLatency", 1},
   };
   EXPECT_THAT(histogram_tester.GetTotalCountsForPrefix("EventLatency."),
@@ -114,6 +124,16 @@ IN_PROC_BROWSER_TEST_F(EventLatencyBrowserTest, KeyPressOnButtonWithAnimation) {
   FetchHistogramsFromChildProcesses();
 
   base::HistogramTester::CountsMap expected_counts = {
+      {"EventLatency.KeyReleased.BrowserToRendererCompositor", 1},
+      {"EventLatency.KeyReleased.BeginImplFrameToSendBeginMainFrame", 1},
+      {"EventLatency.KeyReleased.SendBeginMainFrameToCommit", 1},
+      {"EventLatency.KeyReleased.Commit", 1},
+      {"EventLatency.KeyReleased.EndCommitToActivation", 1},
+      {"EventLatency.KeyReleased.Activation", 1},
+      {"EventLatency.KeyReleased.EndActivateToSubmitCompositorFrame", 1},
+      {"EventLatency.KeyReleased."
+       "SubmitCompositorFrameToPresentationCompositorFrame",
+       1},
       {"EventLatency.KeyReleased.TotalLatency", 1},
   };
   EXPECT_THAT(histogram_tester.GetTotalCountsForPrefix("EventLatency."),