Add time to next paint UKM for each input event.

UKM privacy review: https://docs.google.com/document/d/1DpX7LvTIAzXPP3KUOlEeGpwrzAH3eVFH0vE0w3-RNpM/edit?usp=sharing

Change-Id: Ie175254aa965ec7529506eebea4f90fdaba462f4
Bug: 1139533
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2533590Reviewed-by: Steve Kobes <skobes@chromium.org>
Reviewed-by: Nicolás Peña Moreno <npm@chromium.org>
Reviewed-by: Robert Kaplow <rkaplow@chromium.org>
Commit-Queue: Hongbo Song <hbsong@google.com>
Cr-Commit-Position: refs/heads/master@{#840675}

third_party/blink/renderer/core/loader/interactive_detector.cc

@@ -243,7 +243,7 @@ void InteractiveDetector::HandleForInputDelay(
     delay = processing_start - event_platform_timestamp;
     event_timestamp = event_platform_timestamp;
   }
-
+  pending_pointerdown_delay_ = base::TimeDelta();
   pending_pointerdown_timestamp_ = base::TimeTicks();
   bool interactive_timing_metrics_changed = false;
 
@@ -638,46 +638,16 @@ void InteractiveDetector::SetUkmRecorderForTesting(
 }
 
 void InteractiveDetector::RecordInputEventTimingUKM(
-    const Event& event,
-    base::TimeTicks event_timestamp,
-    base::TimeTicks processing_start,
-    base::TimeTicks processing_end) {
-  DCHECK(event.isTrusted());
-
-  // This only happens sometimes on tests unrelated to InteractiveDetector. It
-  // is safe to ignore events that are not properly initialized.
-  if (event_timestamp.is_null())
-    return;
-
-  // We can't report a pointerDown until the pointerUp, in case it turns into a
-  // scroll.
-  if (event.type() == event_type_names::kPointerdown) {
-    pending_pointerdown_processing_time_ = processing_end - processing_start;
-    return;
-  }
-
-  base::TimeDelta input_delay;
-  base::TimeDelta processing_time;
-  if (event.type() == event_type_names::kPointerup) {
-    // PointerUp by itself is not considered a significant input.
-    if (!pending_pointerdown_processing_time_)
-      return;
-
-    input_delay = pending_pointerdown_delay_;
-    processing_time = pending_pointerdown_processing_time_.value();
-  } else {
-    processing_time = processing_end - processing_start;
-    input_delay = processing_start - event_timestamp;
-  }
-  pending_pointerdown_delay_ = base::TimeDelta();
-  pending_pointerdown_processing_time_ = base::nullopt;
-
-  // Record InputDelay and Input Event Processing Time UKM.
+    base::TimeDelta input_delay,
+    base::TimeDelta processing_time,
+    base::TimeDelta time_to_next_paint) {
   ukm::SourceId source_id = GetSupplementable()->UkmSourceID();
   DCHECK_NE(source_id, ukm::kInvalidSourceId);
   ukm::builders::InputEvent(source_id)
       .SetInteractiveTiming_InputDelay(input_delay.InMilliseconds())
       .SetInteractiveTiming_ProcessingTime(processing_time.InMilliseconds())
+      .SetInteractiveTiming_ProcessingFinishedToNextPaint(
+          time_to_next_paint.InMilliseconds())
       .Record(GetUkmRecorder());
 
   if (!page_event_times_.first_input_processing_time) {

third_party/blink/renderer/core/loader/interactive_detector.h

@@ -130,10 +130,9 @@ class CORE_EXPORT InteractiveDetector
 
   void SetUkmRecorderForTesting(ukm::UkmRecorder* test_ukm_recorder);
 
-  void RecordInputEventTimingUKM(const Event& event,
-                                 base::TimeTicks event_timestamp,
-                                 base::TimeTicks processing_start,
-                                 base::TimeTicks processing_end);
+  void RecordInputEventTimingUKM(base::TimeDelta input_delay,
+                                 base::TimeDelta processing_time,
+                                 base::TimeDelta time_to_next_paint);
 
   void DidObserveFirstScrollDelay(base::TimeDelta first_scroll_delay,
                                   base::TimeTicks first_scroll_timestamp);
@@ -228,10 +227,6 @@ class CORE_EXPORT InteractiveDetector
   void OnLongTaskDetected(base::TimeTicks start_time,
                           base::TimeTicks end_time) override;
 
-  // The duration of event handlers processing the event for the previous
-  // pointer down.
-  base::Optional<base::TimeDelta> pending_pointerdown_processing_time_;
-
   // The duration between the hardware timestamp and when we received the event
   // for the previous pointer down. Only non-zero if we've received a pointer
   // down event, and haven't yet reported the first input delay.

third_party/blink/renderer/core/loader/interactive_detector_test.cc

@@ -568,28 +568,26 @@ TEST_F(InteractiveDetectorTest, LongTaskAfterTTIDoesNothing) {
 }
 
 TEST_F(InteractiveDetectorTest, RecordInputDelayUKM) {
-  base::TimeDelta delay = base::TimeDelta::FromMilliseconds(20);
+  base::TimeDelta input_delay = base::TimeDelta::FromMilliseconds(20);
   base::TimeDelta processing_time = base::TimeDelta::FromMilliseconds(10);
-  Event event;
-  event.SetTrusted(true);
-  event.SetType(event_type_names::kClick);
-  base::TimeTicks processing_start = Now() + delay;
-  base::TimeTicks event_platform_timestamp = Now();
-  base::TimeTicks processing_end = processing_start + processing_time;
+  base::TimeDelta time_to_next_paint = base::TimeDelta::FromMilliseconds(10);
 
   ukm::TestAutoSetUkmRecorder test_ukm_recorder;
   GetDetector()->SetUkmRecorderForTesting(&test_ukm_recorder);
-  GetDetector()->RecordInputEventTimingUKM(event, event_platform_timestamp,
-                                           processing_start, processing_end);
+  GetDetector()->RecordInputEventTimingUKM(input_delay, processing_time,
+                                           time_to_next_paint);
   auto entries = test_ukm_recorder.GetEntriesByName(InputEvent::kEntryName);
   EXPECT_EQ(1ul, entries.size());
   auto* entry = entries[0];
   test_ukm_recorder.ExpectEntryMetric(
       entry, InputEvent::kInteractiveTiming_InputDelayName,
-      delay.InMilliseconds());
+      input_delay.InMilliseconds());
   test_ukm_recorder.ExpectEntryMetric(
       entry, InputEvent::kInteractiveTiming_ProcessingTimeName,
       processing_time.InMilliseconds());
+  test_ukm_recorder.ExpectEntryMetric(
+      entry, InputEvent::kInteractiveTiming_ProcessingFinishedToNextPaintName,
+      time_to_next_paint.InMilliseconds());
   EXPECT_EQ(
       GetDetector()->GetFirstInputProcessingTime().value().InMilliseconds(),
       processing_time.InMilliseconds());

third_party/blink/renderer/core/timing/event_timing.cc

@@ -116,14 +116,6 @@ void EventTiming::DidDispatchEvent(const Event& event, Document& document) {
   performance_->RegisterEventTiming(event.type(), event_timestamp_,
                                     processing_start_, processing_end,
                                     event.cancelable(), target);
-  if (should_log_event_) {
-    InteractiveDetector* interactive_detector =
-        InteractiveDetector::From(document);
-    if (interactive_detector) {
-      interactive_detector->RecordInputEventTimingUKM(
-          event, event_timestamp_, processing_start_, processing_end);
-    }
-  }
 }
 
 // static

third_party/blink/renderer/core/timing/window_performance.cc

@@ -44,6 +44,7 @@
 #include "third_party/blink/renderer/core/html/html_frame_owner_element.h"
 #include "third_party/blink/renderer/core/inspector/console_message.h"
 #include "third_party/blink/renderer/core/loader/document_loader.h"
+#include "third_party/blink/renderer/core/loader/interactive_detector.h"
 #include "third_party/blink/renderer/core/page/chrome_client.h"
 #include "third_party/blink/renderer/core/page/page.h"
 #include "third_party/blink/renderer/core/page/page_hidden_state.h"
@@ -397,7 +398,35 @@ void WindowPerformance::ReportEventTimings(uint64_t frame_index,
     event_frames_.pop_front();
 
     int duration_in_ms = std::round((end_time - entry->startTime()) / 8) * 8;
+    base::TimeDelta input_delay = base::TimeDelta::FromMillisecondsD(
+        entry->processingStart() - entry->startTime());
+    base::TimeDelta processing_time = base::TimeDelta::FromMillisecondsD(
+        entry->processingEnd() - entry->processingStart());
+    base::TimeDelta time_to_next_paint =
+        base::TimeDelta::FromMillisecondsD(end_time - entry->processingEnd());
+    InteractiveDetector* interactive_detector =
+        DomWindow() ? InteractiveDetector::From(*(DomWindow()->document()))
+                    : nullptr;
     entry->SetDuration(duration_in_ms);
+    if (entry->name() == "pointerdown") {
+      pending_pointer_down_input_delay_ = input_delay;
+      pending_pointer_down_processing_time_ = processing_time;
+      pending_pointer_down_time_to_next_paint_ = time_to_next_paint;
+    } else if (entry->name() == "pointerup") {
+      if (pending_pointer_down_time_to_next_paint_.has_value() &&
+          interactive_detector) {
+        interactive_detector->RecordInputEventTimingUKM(
+            pending_pointer_down_input_delay_.value(),
+            pending_pointer_down_processing_time_.value(),
+            pending_pointer_down_time_to_next_paint_.value());
+      }
+    } else if ((entry->name() == "click" || entry->name() == "keydown" ||
+                entry->name() == "mousedown") &&
+               interactive_detector) {
+      interactive_detector->RecordInputEventTimingUKM(
+          input_delay, processing_time, time_to_next_paint);
+    }
+
     if (!first_input_timing_) {
       if (entry->name() == "pointerdown") {
         first_pointer_down_event_timing_ =

third_party/blink/renderer/core/timing/window_performance.h

@@ -155,6 +155,9 @@ class CORE_EXPORT WindowPerformance final : public Performance,
   Member<EventCounts> event_counts_;
   mutable Member<PerformanceNavigation> navigation_;
   mutable Member<PerformanceTiming> timing_;
+  base::Optional<base::TimeDelta> pending_pointer_down_input_delay_;
+  base::Optional<base::TimeDelta> pending_pointer_down_processing_time_;
+  base::Optional<base::TimeDelta> pending_pointer_down_time_to_next_paint_;
 };
 
 }  // namespace blink

tools/metrics/ukm/ukm.xml

@@ -5922,6 +5922,22 @@ be describing additional metrics about the same event.
       </history>
     </aggregation>
   </metric>
+  <metric name="InteractiveTiming.ProcessingFinishedToNextPaint">
+    <summary>
+      Measures the time in ms from when the event handlers finish processing the
+      input event to the time when the next paint caused by the input event is
+      performed.
+    </summary>
+    <aggregation>
+      <history>
+        <index fields="profile.is_dominant_version"/>
+        <index fields="profile.is_latest_version"/>
+        <statistics>
+          <quantiles type="std-percentiles"/>
+        </statistics>
+      </history>
+    </aggregation>
+  </metric>
   <metric name="InteractiveTiming.ProcessingTime">
     <summary>
       Measures Input Event processing time, the duration of event handlers