From f95480a21202c8d584c9214cc524240d1ae4f95c Mon Sep 17 00:00:00 2001
From: Mustaq Ahmed <[email protected]>
Date: Tue, 04 Jun 2024 19:41:30 +0000
Subject: [PATCH] Add a new histogram to log missing first paint after event dispatch.

Our data suggests that the existing SuppressedEventsTimingBeforePaint
is perhaps affected by noisy first paint timing.  Moreover, our
timeout logic was affected in the wild by early initialization of
WidgetInputHandlerManager through pre-rendering.

This CL updates the related histograms as follows:
- adds the histogram SuppressedEventsBeforeMissingFirstPaint that is
  logged only if no paint signal is received in 15sec after the first
  event dispatch, and
- logging of 3 existing histograms is modified very slightly: the
  timeout bucket will be logged 15 sec after the first dispatch (vs
  after WIHM initiation).

OBSOLETE_HISTOGRAM[PageLoad.Internal.SuppressedEventsCountBeforePaint2]=Replaced by PageLoad.Internal.SuppressedEventsCountBeforePaint3
OBSOLETE_HISTOGRAM[PageLoad.Internal.SuppressedEventsTimingBeforePaint2]=Replaced by PageLoad.Internal.SuppressedEventsTimingBeforePaint3
OBSOLETE_HISTOGRAM[PageLoad.Internal.SuppressedInteractionsCountBeforePaint2]=Replaced by PageLoad.Internal.SuppressedInteractionsCountBeforePaint3

Bug: 40057499
Change-Id: I0c058cc485c89e8864704bb0676eafe01709e90d
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/5485266
Auto-Submit: Mustaq Ahmed <[email protected]>
Reviewed-by: Robert Flack <[email protected]>
Commit-Queue: Mustaq Ahmed <[email protected]>
Reviewed-by: Ian Clelland <[email protected]>
Cr-Commit-Position: refs/heads/main@{#1310120}
---

diff --git a/third_party/blink/renderer/platform/widget/input/widget_input_handler_manager.cc b/third_party/blink/renderer/platform/widget/input/widget_input_handler_manager.cc
index ce789f4..861ccef 100644
--- a/third_party/blink/renderer/platform/widget/input/widget_input_handler_manager.cc
+++ b/third_party/blink/renderer/platform/widget/input/widget_input_handler_manager.cc
@@ -464,18 +464,17 @@
     std::optional<base::TimeTicks> first_paint_time) {
   CHECK(main_thread_task_runner_->BelongsToCurrentThread());
 
-  bool first_paint_max_delay_reached = !first_paint_time.has_value();
-
-  if (!first_paint_max_delay_reached) {
-    if (first_paint_max_delay_timer_ &&
-        first_paint_max_delay_timer_->IsRunning()) {
-      // Prevent the timer from recording the histograms again.
-      first_paint_max_delay_timer_->Stop();
-    } else {
-      // The histograms are already recorded by the timer.
-      return;
-    }
+  if (recorded_event_metric_for_paint_timing_) {
+    return;
   }
+  recorded_event_metric_for_paint_timing_ = true;
+
+  if (first_paint_max_delay_timer_ &&
+      first_paint_max_delay_timer_->IsRunning()) {
+    first_paint_max_delay_timer_->Stop();
+  }
+
+  bool first_paint_max_delay_reached = !first_paint_time.has_value();
 
   // Initialize to 0 timestamp and log 0 if there was no suppressed event or
   // the most recent suppressed event was before the first_paint_time
@@ -496,13 +495,28 @@
     suppressed_events_count = uma_data_.suppressed_events_count;
   }
 
-  UMA_HISTOGRAM_TIMES("PageLoad.Internal.SuppressedEventsTimingBeforePaint2",
+  UMA_HISTOGRAM_TIMES("PageLoad.Internal.SuppressedEventsTimingBeforePaint3",
                       diff);
   UMA_HISTOGRAM_COUNTS(
-      "PageLoad.Internal.SuppressedInteractionsCountBeforePaint2",
+      "PageLoad.Internal.SuppressedInteractionsCountBeforePaint3",
       suppressed_interactions_count);
-  UMA_HISTOGRAM_COUNTS("PageLoad.Internal.SuppressedEventsCountBeforePaint2",
+  UMA_HISTOGRAM_COUNTS("PageLoad.Internal.SuppressedEventsCountBeforePaint3",
                        suppressed_events_count);
+  UMA_HISTOGRAM_BOOLEAN(
+      "PageLoad.Internal.SuppressedEventsBeforeMissingFirstPaint",
+      first_paint_max_delay_reached);
+}
+
+void WidgetInputHandlerManager::StartFirstPaintMaxDelayTimer() {
+  if (first_paint_max_delay_timer_ || recorded_event_metric_for_paint_timing_) {
+    return;
+  }
+  first_paint_max_delay_timer_ = std::make_unique<base::OneShotTimer>();
+  first_paint_max_delay_timer_->Start(
+      FROM_HERE, kFirstPaintMaxAcceptableDelay,
+      base::BindOnce(
+          &WidgetInputHandlerManager::RecordEventMetricsForPaintTiming, this,
+          std::nullopt));
 }
 
 void WidgetInputHandlerManager::DispatchScrollGestureToCompositor(
@@ -561,6 +575,15 @@
     }
   }
 
+  if (!widget_is_embedded_ &&
+      (suppressing_input_events_state_ &
+       static_cast<uint16_t>(SuppressingInputEventsBits::kHasNotPainted))) {
+    main_thread_task_runner_->PostTask(
+        FROM_HERE,
+        base::BindOnce(&WidgetInputHandlerManager::StartFirstPaintMaxDelayTimer,
+                       this));
+  }
+
   // Drop input if we are deferring a rendering pipeline phase, unless it's a
   // move event, or we are waiting for first visually non empty paint.
   // We don't want users interacting with stuff they can't see, so we drop it.
@@ -777,22 +800,8 @@
   suppressing_input_events_state_ =
       static_cast<uint16_t>(SuppressingInputEventsBits::kHasNotPainted);
 
-  // The following code assumes that for a single page load, the two calls to
-  // this method (from WIHM ctor and from WFWI::DidNavigate) are made within
-  // a time gap of kFirstPaintMaxAcceptableDelay.  If this is not true (very
-  // unlikely), the UMA will be double-counted!
-  if (!first_paint_max_delay_timer_) {
-    first_paint_max_delay_timer_ = std::make_unique<base::OneShotTimer>();
-  } else {
-    first_paint_max_delay_timer_->Stop();
-  }
-  if (!widget_is_embedded_) {
-    first_paint_max_delay_timer_->Start(
-        FROM_HERE, kFirstPaintMaxAcceptableDelay,
-        base::BindOnce(
-            &WidgetInputHandlerManager::RecordEventMetricsForPaintTiming, this,
-            std::nullopt));
-  }
+  first_paint_max_delay_timer_.reset();
+  recorded_event_metric_for_paint_timing_ = false;
 
   base::AutoLock lock(uma_data_lock_);
   uma_data_.have_emitted_uma = false;
@@ -1150,6 +1159,7 @@
 
 void WidgetInputHandlerManager::ClearClient() {
   first_paint_max_delay_timer_.reset();
+  recorded_event_metric_for_paint_timing_ = false;
   input_event_queue_->ClearClient();
 }
 
diff --git a/third_party/blink/renderer/platform/widget/input/widget_input_handler_manager.h b/third_party/blink/renderer/platform/widget/input/widget_input_handler_manager.h
index 1fab2a6e..471cbfc4 100644
--- a/third_party/blink/renderer/platform/widget/input/widget_input_handler_manager.h
+++ b/third_party/blink/renderer/platform/widget/input/widget_input_handler_manager.h
@@ -295,6 +295,10 @@
   void RecordEventMetricsForPaintTiming(
       std::optional<base::TimeTicks> first_paint_time);
 
+  // Start `first_paint_max_delay_timer_` if not started already.  This runs on
+  // the main thread.
+  void StartFirstPaintMaxDelayTimer();
+
   // Helpers for FlushEventQueuesForTesting.
   void FlushCompositorQueueForTesting();
   void FlushMainThreadQueueForTesting(base::OnceClosure done);
@@ -403,6 +407,10 @@
   // thread.
   std::unique_ptr<base::OneShotTimer> first_paint_max_delay_timer_;
 
+  // Tracks whether `RecordEventMetricsForPaintTiming` has already recorded the
+  // UMA related to first paint.
+  bool recorded_event_metric_for_paint_timing_ = false;
+
   unsigned dropped_pointer_down_ = 0;
 
 #if BUILDFLAG(IS_ANDROID)
diff --git a/tools/metrics/histograms/metadata/page/histograms.xml b/tools/metrics/histograms/metadata/page/histograms.xml
index 7ee54026..81904e93 100644
--- a/tools/metrics/histograms/metadata/page/histograms.xml
+++ b/tools/metrics/histograms/metadata/page/histograms.xml
@@ -2696,26 +2696,37 @@
   </summary>
 </histogram>
 
-<histogram name="PageLoad.Internal.SuppressedEventsCountBeforePaint2"
+<histogram name="PageLoad.Internal.SuppressedEventsBeforeMissingFirstPaint"
+    enum="Boolean" expires_after="2024-11-17">
+  <owner>[email protected]</owner>
+  <owner>[email protected]</owner>
+  <summary>
+    Records if the first paint signal is not received within 15sec of first
+    event dispatch. A &quot;true&quot; value here is expected to be rare.
+  </summary>
+</histogram>
+
+<histogram name="PageLoad.Internal.SuppressedEventsCountBeforePaint3"
     units="count" expires_after="2024-11-17">
   <owner>[email protected]</owner>
   <owner>[email protected]</owner>
   <summary>
     Records the number of events observed before the first paint.
 
-    This metric is emitted for every committed page load, either at the
-    completion of the first paint or 15sec after navigation (whichever comes