Add total latency up to gpu-swap-end for scroll events

Existing LatencyInfo-based event latency metrics measure the time
between event creation timestamp and gpu-swap-end. To be able to verify
new event latency metrics against them, we need add similar metrics for
new EventLatency metrics. This is only added for scroll events as
LatencyInfo-based metrics only exist for scroll events.

Bug: 1057193
Change-Id: I73169330a4ffb0e4b5fd9506960a5737624867bc
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2129215Reviewed-by: Sadrul Chowdhury <sadrul@chromium.org>
Commit-Queue: Mohsen Izadi <mohsen@chromium.org>
Cr-Commit-Position: refs/heads/master@{#754948}

cc/metrics/compositor_frame_reporter.cc

@@ -188,12 +188,12 @@ std::string GetCompositorLatencyHistogramName(
                        GetStageName(stage_type_index)});
 }
 
-std::string GetEventLatencyHistogramName(const EventMetrics& event_metrics) {
+std::string GetEventLatencyHistogramBaseName(
+    const EventMetrics& event_metrics) {
   const bool is_scroll = event_metrics.scroll_input_type().has_value();
-  return base::StrCat({"EventLatency.", event_metrics.GetTypeName(),
-                       is_scroll ? "." : nullptr,
-                       is_scroll ? event_metrics.GetScrollTypeName() : nullptr,
-                       ".TotalLatency"});
+  return base::StrCat(
+      {"EventLatency.", event_metrics.GetTypeName(), is_scroll ? "." : nullptr,
+       is_scroll ? event_metrics.GetScrollTypeName() : nullptr});
 }
 
 }  // namespace
@@ -529,29 +529,51 @@ void CompositorFrameReporter::ReportCompositorLatencyHistogram(
 
 void CompositorFrameReporter::ReportEventLatencyHistograms() const {
   for (const EventMetrics& event_metrics : events_metrics_) {
-    base::TimeDelta total_latency =
-        frame_termination_time_ - event_metrics.time_stamp();
-    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());
-    const int type_index = static_cast<int>(event_metrics.type());
+    const std::string histogram_base_name =
+        GetEventLatencyHistogramBaseName(event_metrics);
+    const int event_type_index = static_cast<int>(event_metrics.type());
     const int scroll_type_index =
         event_metrics.scroll_input_type()
             ? static_cast<int>(*event_metrics.scroll_input_type())
             : 0;
     const int histogram_index =
-        type_index * kEventLatencyScrollTypeCount + scroll_type_index;
+        event_type_index * kEventLatencyScrollTypeCount + scroll_type_index;
+
+    // For scroll events, report total latency up to gpu-swap-end. This is
+    // useful in comparing new EventLatency metrics with LatencyInfo-based
+    // scroll event latency metrics.
+    if (event_metrics.scroll_input_type() &&
+        !viz_breakdown_.swap_timings.is_null()) {
+      const base::TimeDelta swap_end_latency =
+          viz_breakdown_.swap_timings.swap_end - event_metrics.time_stamp();
+      const std::string swap_end_histogram_name =
+          histogram_base_name + ".TotalLatencyToSwapEnd";
+      STATIC_HISTOGRAM_POINTER_GROUP(
+          swap_end_histogram_name, histogram_index,
+          kMaxEventLatencyHistogramIndex,
+          AddTimeMicrosecondsGranularity(swap_end_latency),
+          base::Histogram::FactoryGet(
+              swap_end_histogram_name, kEventLatencyHistogramMin,
+              kEventLatencyHistogramMax, kEventLatencyHistogramBucketCount,
+              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(
-        GetEventLatencyHistogramName(event_metrics), histogram_index,
-        kMaxEventLatencyHistogramIndex,
+        histogram_name, histogram_index, kMaxEventLatencyHistogramIndex,
         AddTimeMicrosecondsGranularity(total_latency),
         base::Histogram::FactoryGet(
-            GetEventLatencyHistogramName(event_metrics),
-            kEventLatencyHistogramMin, kEventLatencyHistogramMax,
-            kEventLatencyHistogramBucketCount,
+            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

cc/metrics/compositor_frame_reporter_unittest.cc

@@ -13,6 +13,7 @@
 #include "cc/input/scroll_input_type.h"
 #include "cc/metrics/compositor_frame_reporting_controller.h"
 #include "cc/metrics/event_metrics.h"
+#include "components/viz/common/frame_timing_details.h"
 #include "testing/gmock/include/gmock/gmock.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
@@ -36,14 +37,31 @@ class CompositorFrameReporterTest : public testing::Test {
     AdvanceNowByMs(1);
   }
 
+ protected:
   void AdvanceNowByMs(int advance_ms) {
     now_ += base::TimeDelta::FromMicroseconds(advance_ms);
   }
 
   base::TimeTicks Now() { return now_; }
 
- protected:
+  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();
+    return frame_timing_details;
+  }
+
   std::unique_ptr<CompositorFrameReporter> pipeline_reporter_;
+
+ private:
   base::TimeTicks now_;
 };
 
@@ -270,22 +288,40 @@ TEST_F(CompositorFrameReporterTest,
   pipeline_reporter_->SetEventsMetrics(std::move(events_metrics));
 
   AdvanceNowByMs(3);
-  const base::TimeTicks presentation_time = Now();
+  viz::FrameTimingDetails frame_timing_details = BuildFrameTimingDetails();
+  pipeline_reporter_->SetVizBreakdown(frame_timing_details);
   pipeline_reporter_->TerminateFrame(
       CompositorFrameReporter::FrameTerminationStatus::kPresentedFrame,
-      presentation_time);
+      frame_timing_details.presentation_feedback.timestamp);
 
   pipeline_reporter_ = nullptr;
 
-  const int latency_ms = (presentation_time - event_time).InMicroseconds();
+  const int total_latency_ms =
+      (frame_timing_details.presentation_feedback.timestamp - event_time)
+          .InMicroseconds();
+  const int swap_end_latency_ms =
+      (frame_timing_details.swap_timings.swap_end - event_time)
+          .InMicroseconds();
   histogram_tester.ExpectTotalCount(
       "EventLatency.GestureScrollBegin.Wheel.TotalLatency", 1);
+  histogram_tester.ExpectTotalCount(
+      "EventLatency.GestureScrollBegin.Wheel.TotalLatencyToSwapEnd", 1);
   histogram_tester.ExpectTotalCount(
       "EventLatency.GestureScrollUpdate.Wheel.TotalLatency", 2);
+  histogram_tester.ExpectTotalCount(
+      "EventLatency.GestureScrollUpdate.Wheel.TotalLatencyToSwapEnd", 2);
+  histogram_tester.ExpectBucketCount(
+      "EventLatency.GestureScrollBegin.Wheel.TotalLatency", total_latency_ms,
+      1);
+  histogram_tester.ExpectBucketCount(
+      "EventLatency.GestureScrollBegin.Wheel.TotalLatencyToSwapEnd",
+      swap_end_latency_ms, 1);
   histogram_tester.ExpectBucketCount(
-      "EventLatency.GestureScrollBegin.Wheel.TotalLatency", latency_ms, 1);
+      "EventLatency.GestureScrollUpdate.Wheel.TotalLatency", total_latency_ms,
+      2);
   histogram_tester.ExpectBucketCount(
-      "EventLatency.GestureScrollUpdate.Wheel.TotalLatency", latency_ms, 2);
+      "EventLatency.GestureScrollUpdate.Wheel.TotalLatencyToSwapEnd",
+      swap_end_latency_ms, 2);
 }
 
 // Tests that when the frame is not presented to the user, event latency metrics