Add TimeToHandled & IsMainThread input ukm metrics

Add submetric TimeToHandled and also whether the
whole scrolling event happened on main vs impl
to the scrolling UKM events.

Bug: 783874
Change-Id: I34b6832d779f9f5212e3fef23bf219cacc191e57
Reviewed-on: https://chromium-review.googlesource.com/840824
Commit-Queue: Navid Zolghadr <nzolghadr@chromium.org>
Reviewed-by: Robert Kaplow <rkaplow@chromium.org>
Reviewed-by: Dave Tapuska <dtapuska@chromium.org>
Reviewed-by: Timothy Dresser <tdresser@chromium.org>
Cr-Commit-Position: refs/heads/master@{#526795}

content/browser/renderer_host/input/render_widget_host_latency_tracker_unittest.cc

@@ -144,7 +144,7 @@ class RenderWidgetHostLatencyTrackerTest
   }
 
   void ExpectUkmReported(const char* event_name,
-                         const char* metric_name,
+                         const std::vector<std::string>& metric_names,
                          size_t expected_count) {
     const ukm::TestUkmRecorder* ukm_recoder =
         test_browser_client_.GetTestUkmRecorder();
@@ -153,7 +153,9 @@ class RenderWidgetHostLatencyTrackerTest
     EXPECT_EQ(expected_count, entries.size());
     for (const auto* const entry : entries) {
       ukm_recoder->ExpectEntrySourceHasUrl(entry, GURL(kUrl));
-      EXPECT_TRUE(ukm_recoder->EntryHasMetric(entry, metric_name));
+      for (const auto& metric_name : metric_names) {
+        EXPECT_TRUE(ukm_recoder->EntryHasMetric(entry, metric_name.c_str()));
+      }
     }
   }
 
@@ -289,8 +291,10 @@ TEST_F(RenderWidgetHostLatencyTrackerTest, TestWheelToFirstScrollHistograms) {
 
       // UKM metrics.
       total_ukm_entry_count++;
-      ExpectUkmReported("Event.ScrollBegin.Wheel",
-                        "TimeToScrollUpdateSwapBegin", total_ukm_entry_count);
+      ExpectUkmReported(
+          "Event.ScrollBegin.Wheel",
+          {"TimeToScrollUpdateSwapBegin", "TimeToHandled", "IsMainThread"},
+          total_ukm_entry_count);
       // Rappor metrics.
       EXPECT_TRUE(
           RapporSampleAssert("Event.Latency.ScrollUpdate.Touch."
@@ -402,8 +406,10 @@ TEST_F(RenderWidgetHostLatencyTrackerTest, TestWheelToScrollHistograms) {
 
       // UKM metrics.
       total_ukm_entry_count++;
-      ExpectUkmReported("Event.ScrollUpdate.Wheel",
-                        "TimeToScrollUpdateSwapBegin", total_ukm_entry_count);
+      ExpectUkmReported(
+          "Event.ScrollUpdate.Wheel",
+          {"TimeToScrollUpdateSwapBegin", "TimeToHandled", "IsMainThread"},
+          total_ukm_entry_count);
       // Rappor metrics.
       EXPECT_TRUE(
           RapporSampleAssert("Event.Latency.ScrollUpdate.Touch."
@@ -538,8 +544,10 @@ TEST_F(RenderWidgetHostLatencyTrackerTest, TestTouchToFirstScrollHistograms) {
 
     // UKM metrics.
     total_ukm_entry_count++;
-    ExpectUkmReported("Event.ScrollBegin.Touch", "TimeToScrollUpdateSwapBegin",
-                      total_ukm_entry_count);
+    ExpectUkmReported(
+        "Event.ScrollBegin.Touch",
+        {"TimeToScrollUpdateSwapBegin", "TimeToHandled", "IsMainThread"},
+        total_ukm_entry_count);
     // Rappor metrics.
     EXPECT_TRUE(
         RapporSampleAssert("Event.Latency.ScrollUpdate.Touch."
@@ -659,8 +667,10 @@ TEST_F(RenderWidgetHostLatencyTrackerTest, TestTouchToScrollHistograms) {
 
     // UKM metrics.
     total_ukm_entry_count++;
-    ExpectUkmReported("Event.ScrollUpdate.Touch", "TimeToScrollUpdateSwapBegin",
-                      total_ukm_entry_count);
+    ExpectUkmReported(
+        "Event.ScrollUpdate.Touch",
+        {"TimeToScrollUpdateSwapBegin", "TimeToHandled", "IsMainThread"},
+        total_ukm_entry_count);
 
     // Rappor metrics.
     EXPECT_TRUE(

tools/metrics/ukm/ukm.xml

@@ -516,6 +516,18 @@ be describing additional metrics about the same event.
     Metrics related to a scroll action caused by the generated ScrollUpdate
     gesture event.
   </summary>
+  <metric name="IsMainThread">
+    <summary>
+      Whether the event is handled on the main thread or not.
+    </summary>
+  </metric>
+  <metric name="TimeToHandled">
+    <summary>
+      The time in microseconds between initial creation of a touch event and the
+      generated ScrollUpdate gesture event is handled on main/impl thread. If no
+      swap was induced by the ScrollUpdate gesture event, no recording is made.
+    </summary>
+  </metric>
   <metric name="TimeToScrollUpdateSwapBegin">
     <summary>
       The time in microseconds between the initial creation of a touch event and
@@ -532,6 +544,19 @@ be describing additional metrics about the same event.
     Metrics related to first scroll action caused by the generated ScrollUpdate
     gesture event.
   </summary>
+  <metric name="IsMainThread">
+    <summary>
+      Whether the event is handled on the main thread or not.
+    </summary>
+  </metric>
+  <metric name="TimeToHandled">
+    <summary>
+      The time in microseconds between initial creation of a touch event and the
+      first generated ScrollUpdate gesture event in a given scroll gesture event
+      sequence is handled on main/impl thread. If no swap was induced by the
+      ScrollUpdate gesture event, no recording is made.
+    </summary>
+  </metric>
   <metric name="TimeToScrollUpdateSwapBegin">
     <summary>
       The time in microseconds between initial creation of a touch event and the
@@ -550,6 +575,19 @@ be describing additional metrics about the same event.
     Metrics related to a scroll action caused by the generated ScrollUpdate
     gesture event.
   </summary>
+  <metric name="IsMainThread">
+    <summary>
+      Whether the event is handled on the main thread or not.
+    </summary>
+  </metric>
+  <metric name="TimeToHandled">
+    <summary>
+      The time in microseconds between initial creation of a wheel event and the
+      generated ScrollUpdate gesture event is handled on main/impl thread. If no
+      swap was induced by the ScrollUpdate gesture event, no recording is made.
+      The first GSU of every scrolling sequence is excluded from this metric.
+    </summary>
+  </metric>
   <metric name="TimeToScrollUpdateSwapBegin">
     <summary>
       The time in microseconds between the initial creation of a wheel event and
@@ -566,6 +604,19 @@ be describing additional metrics about the same event.
     Metrics related to first scroll action caused by the generated ScrollUpdate
     gesture event.
   </summary>
+  <metric name="IsMainThread">
+    <summary>
+      Whether the event is handled on the main thread or not.
+    </summary>
+  </metric>
+  <metric name="TimeToHandled">
+    <summary>
+      The time in microseconds between initial creation of a wheel event and the
+      first generated ScrollUpdate gesture event in a given scroll gesture event
+      sequence is handled on main/impl thread. If no swap was induced by the
+      ScrollBegin gesture event, no recording is made.
+    </summary>
+  </metric>
   <metric name="TimeToScrollUpdateSwapBegin">
     <summary>
       The time in microseconds between the initial creation of a wheel event and

ui/latency/latency_tracker.cc

@@ -108,11 +108,15 @@ void LatencyTracker::ReportRapporScrollLatency(
 
 void LatencyTracker::ReportUkmScrollLatency(
     const InputMetricEvent& metric_event,
-    const std::string& metric_name,
     const LatencyInfo::LatencyComponent& start_component,
-    const LatencyInfo::LatencyComponent& end_component,
+    const LatencyInfo::LatencyComponent&
+        time_to_scroll_update_swap_begin_component,
+    const LatencyInfo::LatencyComponent& time_to_handled_component,
+    bool is_main_thread,
     const ukm::SourceId ukm_source_id) {
-  CONFIRM_EVENT_TIMES_EXIST(start_component, end_component)
+  CONFIRM_EVENT_TIMES_EXIST(start_component,
+                            time_to_scroll_update_swap_begin_component)
+  CONFIRM_EVENT_TIMES_EXIST(start_component, time_to_handled_component)
 
   // Only report a subset of this metric as the volume is too high.
   if (metric_sampling_ &&
@@ -141,10 +145,17 @@ void LatencyTracker::ReportUkmScrollLatency(
   std::unique_ptr<ukm::UkmEntryBuilder> builder =
       ukm_recorder->GetEntryBuilder(ukm_source_id, event_name.c_str());
   builder->AddMetric(
-      metric_name.c_str(),
-      std::max(static_cast<int64_t>(0), (end_component.last_event_time -
-                                         start_component.first_event_time)
-                                            .InMicroseconds()));
+      "TimeToScrollUpdateSwapBegin",
+      std::max(static_cast<int64_t>(0),
+               (time_to_scroll_update_swap_begin_component.last_event_time -
+                start_component.first_event_time)
+                   .InMicroseconds()));
+  builder->AddMetric("TimeToHandled",
+                     std::max(static_cast<int64_t>(0),
+                              (time_to_handled_component.last_event_time -
+                               start_component.first_event_time)
+                                  .InMicroseconds()));
+  builder->AddMetric("IsMainThread", is_main_thread);
 }
 
 void LatencyTracker::ComputeEndToEndLatencyHistograms(
@@ -181,12 +192,6 @@ void LatencyTracker::ComputeEndToEndLatencyHistograms(
                                   ".TimeToScrollUpdateSwapBegin2",
                               original_component, gpu_swap_begin_component);
 
-    ReportUkmScrollLatency(input_modality == "Touch"
-                               ? InputMetricEvent::SCROLL_BEGIN_TOUCH
-                               : InputMetricEvent::SCROLL_BEGIN_WHEEL,
-                           "TimeToScrollUpdateSwapBegin", original_component,
-                           gpu_swap_begin_component, latency.ukm_source_id());
-
   } else if (latency.FindLatency(
                  ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT,
                  &original_component)) {
@@ -209,11 +214,6 @@ void LatencyTracker::ComputeEndToEndLatencyHistograms(
                                   ".TimeToScrollUpdateSwapBegin2",
                               original_component, gpu_swap_begin_component);
 
-    ReportUkmScrollLatency(input_modality == "Touch"
-                               ? InputMetricEvent::SCROLL_UPDATE_TOUCH
-                               : InputMetricEvent::SCROLL_UPDATE_WHEEL,
-                           "TimeToScrollUpdateSwapBegin", original_component,
-                           gpu_swap_begin_component, latency.ukm_source_id());
   } else if (latency.FindLatency(ui::INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT, 0,
                                  &original_component)) {
     if (input_modality == "KeyPress") {
@@ -239,6 +239,23 @@ void LatencyTracker::ComputeEndToEndLatencyHistograms(
         &rendering_scheduled_component);
     DCHECK_AND_RETURN_ON_FAIL(found_component);
   }
+  if (input_modality == "Touch" || input_modality == "Wheel") {
+    InputMetricEvent input_metric_event;
+    if (scroll_name == "ScrollBegin") {
+      input_metric_event = input_modality == "Touch"
+                               ? InputMetricEvent::SCROLL_BEGIN_TOUCH
+                               : InputMetricEvent::SCROLL_BEGIN_WHEEL;
+    } else {
+      DCHECK_EQ(scroll_name, "ScrollUpdate");
+      input_metric_event = input_modality == "Touch"
+                               ? InputMetricEvent::SCROLL_UPDATE_TOUCH
+                               : InputMetricEvent::SCROLL_UPDATE_WHEEL;
+    }
+    ReportUkmScrollLatency(
+        input_metric_event, original_component, gpu_swap_begin_component,
+        rendering_scheduled_component, rendering_scheduled_on_main,
+        latency.ukm_source_id());
+  }
 
   const std::string thread_name = rendering_scheduled_on_main ? "Main" : "Impl";
 

ui/latency/latency_tracker.h

@@ -46,9 +46,11 @@ class LatencyTracker {
 
   void ReportUkmScrollLatency(
       const InputMetricEvent& metric_event,
-      const std::string& metric_name,
       const LatencyInfo::LatencyComponent& start_component,
-      const LatencyInfo::LatencyComponent& end_component,
+      const LatencyInfo::LatencyComponent&
+          time_to_scroll_update_swap_begin_component,
+      const LatencyInfo::LatencyComponent& time_to_handled_component,
+      bool is_main_thread,
       const ukm::SourceId ukm_source_id);
 
   void ComputeEndToEndLatencyHistograms(