Log First User Interaction in Page Load Metrics

chrome/browser/page_load_metrics/observers/from_gws_page_load_metrics_observer.cc

Index: chrome/browser/page_load_metrics/observers/from_gws_page_load_metrics_observer.cc
diff --git a/chrome/browser/page_load_metrics/observers/from_gws_page_load_metrics_observer.cc b/chrome/browser/page_load_metrics/observers/from_gws_page_load_metrics_observer.cc
index 612e5cca70428eb8a38deaebfdff20fecf98aa2e..04e405fe8c70c6ae3ec36af350f43e498b6b949e 100644
--- a/chrome/browser/page_load_metrics/observers/from_gws_page_load_metrics_observer.cc
+++ b/chrome/browser/page_load_metrics/observers/from_gws_page_load_metrics_observer.cc
@@ -44,32 +44,46 @@ const char kHistogramFromGWSAbortUnknownNavigationBeforeCommit[] =
 const char kHistogramFromGWSAbortNewNavigationBeforePaint[] =
     "PageLoad.Clients.FromGoogleSearch.AbortTiming.NewNavigation.AfterCommit."
     "BeforePaint";
+const char kHistogramFromGWSAbortNewNavigationBeforeInteraction[] =
+    "PageLoad.Clients.FromGoogleSearch.AbortTiming.NewNavigation.AfterPaint."
+    "BeforeInteraction";
 const char kHistogramFromGWSAbortStopBeforeCommit[] =
     "PageLoad.Clients.FromGoogleSearch.AbortTiming.Stop.BeforeCommit";
 const char kHistogramFromGWSAbortStopBeforePaint[] =
     "PageLoad.Clients.FromGoogleSearch.AbortTiming.Stop.AfterCommit."
     "BeforePaint";
+const char kHistogramFromGWSAbortStopBeforeInteraction[] =
+    "PageLoad.Clients.FromGoogleSearch.AbortTiming.Stop.AfterPaint."
+    "BeforeInteraction";
 const char kHistogramFromGWSAbortCloseBeforeCommit[] =
     "PageLoad.Clients.FromGoogleSearch.AbortTiming.Close.BeforeCommit";
 const char kHistogramFromGWSAbortCloseBeforePaint[] =
     "PageLoad.Clients.FromGoogleSearch.AbortTiming.Close.AfterCommit."
     "BeforePaint";
-
+const char kHistogramFromGWSAbortCloseBeforeInteraction[] =
+    "PageLoad.Clients.FromGoogleSearch.AbortTiming.Close.AfterPaint."
+    "BeforeInteraction";
 const char kHistogramFromGWSAbortOtherBeforeCommit[] =
     "PageLoad.Clients.FromGoogleSearch.AbortTiming.Other.BeforeCommit";
 const char kHistogramFromGWSAbortReloadBeforePaint[] =
     "PageLoad.Clients.FromGoogleSearch.AbortTiming.Reload.AfterCommit."
     "BeforePaint";
+const char kHistogramFromGWSAbortReloadBeforeInteraction[] =
+    "PageLoad.Clients.FromGoogleSearch.AbortTiming.Reload.AfterPaint."
+    "BeforeInteraction";
 const char kHistogramFromGWSAbortForwardBackBeforePaint[] =
     "PageLoad.Clients.FromGoogleSearch.AbortTiming.ForwardBackNavigation."
     "AfterCommit.BeforePaint";
+const char kHistogramFromGWSAbortForwardBackBeforeInteraction[] =
+    "PageLoad.Clients.FromGoogleSearch.AbortTiming.ForwardBackNavigation."
+    "AfterPaint.BeforeInteraction";
 
 }  // namespace internal
 
 namespace {
 
 void LogCommittedAbortsBeforePaint(UserAbortType abort_type,
-                        base::TimeDelta time_to_abort) {
+                                   base::TimeDelta time_to_abort) {
   switch (abort_type) {
     case UserAbortType::ABORT_STOP:
       PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSAbortStopBeforePaint,
@@ -101,6 +115,41 @@ void LogCommittedAbortsBeforePaint(UserAbortType abort_type,
   }
 }
 
+void LogAbortsAfterPaintBeforeInteraction(UserAbortType abort_type,
+                                          base::TimeDelta time_to_abort) {
+  switch (abort_type) {
+    case UserAbortType::ABORT_STOP:
+      PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSAbortStopBeforeInteraction,
+                          time_to_abort);
+      break;
+    case UserAbortType::ABORT_CLOSE:
+      PAGE_LOAD_HISTOGRAM(
+          internal::kHistogramFromGWSAbortCloseBeforeInteraction,
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_NEW_NAVIGATION:
+      PAGE_LOAD_HISTOGRAM(
+          internal::kHistogramFromGWSAbortNewNavigationBeforeInteraction,
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_RELOAD:
+      PAGE_LOAD_HISTOGRAM(
+          internal::kHistogramFromGWSAbortReloadBeforeInteraction,
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_FORWARD_BACK:
+      PAGE_LOAD_HISTOGRAM(
+          internal::kHistogramFromGWSAbortForwardBackBeforeInteraction,
+          time_to_abort);
+      break;
+    default:
+      // These should only be logged for provisional aborts.
+      DCHECK_NE(abort_type, UserAbortType::ABORT_OTHER);
+      DCHECK_NE(abort_type, UserAbortType::ABORT_UNKNOWN_NAVIGATION);
+      break;
+  }
+}
+
 void LogProvisionalAborts(UserAbortType abort_type,
                           base::TimeDelta time_to_abort) {
   switch (abort_type) {
@@ -151,6 +200,31 @@ bool WasAbortedInForeground(UserAbortType abort_type,
   return false;
 }
 
+bool WasAbortedBeforeInteraction(UserAbortType abort_type,
+                                 base::TimeDelta time_to_interaction,
+                                 base::TimeDelta time_to_abort) {
+  if (time_to_interaction.is_zero())

[Bryan McQuade, 2016/05/31 20:33:29]

let's add:
DCHECK(!time_to_abort.is_null());
at the beginning of this function

[mushan1, 2016/06/01 06:53:07]

Done.

+    return true;
+
+  // For the case the abort is a reload or forward_back. Since pull to
+  // reload / forward_back is the most common user case such aborts being
+  // triggered, add a sanitization threshold here: if the first user
+  // interaction are received before a reload / forward_back in a very
+  // short time, treat the interaction as a gesture to perform the abort.
+
+  // Why 1000ms?
+  // 1000ms is enough to perform a pull to reload / forward_back gesture.
+  // It's also too short a time for a user to consume any content

[Bryan McQuade, 2016/05/31 20:33:29]

i'm a little concerned about the fact that histograms with different names end
up with subtly but possibly important differences in behavior.

for example:
PageLoad.Clients.FromGoogleSearch.AbortTiming.ForwardBackNavigation.AfterPaint.BeforeInteraction
will only log when there's 1000ms passed, whereas
PageLoad.Clients.FromGoogleSearch.AbortTiming.NewNavigation.AfterPaint.BeforeInteraction
will log regardless of the delay. This makes comparing results in the two
histograms a bit tricky, since they're really tracking quite different things.

To be clear about this, I think we should give the histograms that incorporate
the delay different names. Perhaps:
PageLoad.Clients.FromGoogleSearch.AbortTiming.ForwardBackNavigation.AfterPaint.BeforeInteractionWith1sDelay
Can we use this name or something similar? That way, the naming will make it
really clear that these histograms are different.

[mushan1, 2016/06/01 06:53:07]

Agree. I made it
'PageLoad.Clients.FromGoogleSearch.AbortTiming.ForwardBackNavigation.AfterPaint.Before1sDelayedInteraction'
now.

Also, I might misinterpret your words here. But to keep us in the same page, the
logic here is, reload and forward_back will be logged EVEN before 1000ms passed
of the first user interaction. Whereas other types of abort will only be logged
exactly before the first user interaction.

+  // revealed by the interaction.
+  if (abort_type == UserAbortType::ABORT_RELOAD ||
+      abort_type == UserAbortType::ABORT_FORWARD_BACK) {
+    return time_to_interaction + base::TimeDelta::FromMilliseconds(1000) >
+           time_to_abort;
+  } else {
+    return time_to_interaction > time_to_abort;
+  }
+}
+
 }  // namespace
 
 // See
@@ -329,6 +403,8 @@ void FromGWSPageLoadMetricsObserver::OnCommit(
                                    ui::PAGE_TRANSITION_LINK) &&
       ui::PageTransitionIsNewNavigation(
           navigation_handle->GetPageTransition()));
+
+  logger_.SetNavigationStart(navigation_handle->NavigationStart());
 }
 
 void FromGWSPageLoadMetricsObserver::OnDomContentLoadedEventStart(
@@ -385,6 +461,11 @@ void FromGWSPageLoadMetricsObserver::OnComplete(
   logger_.OnComplete(timing, extra_info);
 }
 
+void FromGWSPageLoadMetricsObserver::OnUserInput(
+    const blink::WebInputEvent& event) {
+  logger_.OnUserInput(event);
+}
+
 void FromGWSPageLoadMetricsLogger::OnComplete(
     const page_load_metrics::PageLoadTiming& timing,
     const page_load_metrics::PageLoadExtraInfo& extra_info) {
@@ -398,19 +479,24 @@ void FromGWSPageLoadMetricsLogger::OnComplete(
   // loads when tracking aborts after commit.
   UserAbortType abort_type = extra_info.abort_type;
   base::TimeDelta time_to_abort = extra_info.time_to_abort;
-  bool aborted_in_foreground =
-      WasAbortedInForeground(abort_type, time_to_abort, extra_info);
-
-  if (!extra_info.committed_url.is_empty()) {
-    bool aborted_before_paint =
-        aborted_in_foreground && !timing.IsEmpty() &&
-        (timing.first_paint.is_zero() || timing.first_paint >= time_to_abort);
-    if (aborted_before_paint)
-      LogCommittedAbortsBeforePaint(abort_type, time_to_abort);
-  } else {
-    if (aborted_in_foreground)
-      LogProvisionalAborts(abort_type, time_to_abort);
+  if (!WasAbortedInForeground(abort_type, time_to_abort, extra_info))
+    return;
+
+  if (extra_info.committed_url.is_empty()) {
+    LogProvisionalAborts(abort_type, time_to_abort);
+    return;
   }
+
+  // If we didn't receive any timing data but did commit, this is likely not a
+  // renderer-tracked navigation, so ignore it.
+  if (timing.IsEmpty())
+    return;
+
+  if (timing.first_paint.is_zero() || timing.first_paint >= time_to_abort)

[Bryan McQuade, 2016/05/31 20:33:29]

this code uses >= but your WasAbortedBeforeInteraction uses strictly greater
than.

Charles or Shivani can give guidance on which one is preferred, but we should be
consistent.

[mushan1, 2016/06/01 06:53:07]

Change to >= for consistency.

+    LogCommittedAbortsBeforePaint(abort_type, time_to_abort);
+  else if (WasAbortedBeforeInteraction(
+               abort_type, first_user_interaction_after_paint_, time_to_abort))
+    LogAbortsAfterPaintBeforeInteraction(abort_type, time_to_abort);
 }
 
 bool FromGWSPageLoadMetricsLogger::ShouldLogMetrics(const GURL& committed_url) {
@@ -487,6 +573,7 @@ void FromGWSPageLoadMetricsLogger::OnFirstPaint(
     PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSFirstPaint,
                         timing.first_paint);
   }
+  first_paint_triggered_ = true;
 }
 
 void FromGWSPageLoadMetricsLogger::OnFirstTextPaint(
@@ -544,3 +631,12 @@ void FromGWSPageLoadMetricsLogger::OnParseStop(
                         timing.parse_stop - timing.parse_start);
   }
 }
+
+void FromGWSPageLoadMetricsLogger::OnUserInput(
+    const blink::WebInputEvent& event) {
+  if (first_paint_triggered_ && first_user_interaction_after_paint_.is_zero()) {
+    DCHECK(!navigation_start_.is_null());
+    first_user_interaction_after_paint_ =
+        base::TimeTicks::Now() - navigation_start_;
+  }
+}