[ Don't commit ] Add FromGWS variants to the AbortTiming 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 b6c1a7fc8ca150e79acc084c8dec6d57efb1e388..15160ff6eb72c6094f41c5d8d25061a3a6de7ac7 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
@@ -11,6 +11,8 @@
 #include "components/page_load_metrics/common/page_load_timing.h"
 #include "net/base/registry_controlled_domains/registry_controlled_domain.h"
 
+using page_load_metrics::UserAbortType;
+
 namespace internal {
 
 const char kHistogramFromGWSFirstPaint[] =
@@ -32,6 +34,199 @@ const char kHistogramFromGWSLoad[] =
 
 }  // namespace internal
 
+namespace {
+
+void LogCommittedAborts(UserAbortType abort_type,
+                        base::TimeDelta time_to_abort) {
+  switch (abort_type) {
+    case UserAbortType::ABORT_STOP:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.AbortTiming.Stop.AfterCommit.BeforePaint",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_CLOSE:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.AbortTiming.Close.AfterCommit.BeforePaint",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_NEW_NAVIGATION:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.AbortTiming.NewNavigation.AfterCommit."
+          "BeforePaint",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_RELOAD:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.AbortTiming.Reload.AfterCommit."
+          "BeforePaint",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_FORWARD_BACK:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.AbortTiming.ForwardBackNavigation."
+          "AfterCommit.BeforePaint",
+          time_to_abort);
+      break;
+    default:
+      break;
+  }
+}
+
+void LogCommittedAbortsUsingOpener(UserAbortType abort_type,
+                                     base::TimeDelta time_to_abort) {
+  switch (abort_type) {
+    case UserAbortType::ABORT_STOP:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.Opener.AbortTiming.Stop.AfterCommit."
+          "BeforePaint",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_CLOSE:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.Opener.AbortTiming.Close.AfterCommit."
+          "BeforePaint",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_NEW_NAVIGATION:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.Opener.AbortTiming.NewNavigation."
+          "AfterCommit.BeforePaint",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_RELOAD:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.Opener.AbortTiming.Reload.AfterCommit."
+          "BeforePaint",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_FORWARD_BACK:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.Opener.AbortTiming."
+          "ForwardBackNavigation.AfterCommit.BeforePaint",
+          time_to_abort);
+      break;
+    default:
+      break;
+  }
+}
+
+void LogProvisionalAborts(UserAbortType abort_type,
+                          base::TimeDelta time_to_abort) {
+  switch (abort_type) {
+    case UserAbortType::ABORT_STOP:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.AbortTiming.Stop.BeforeCommit",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_CLOSE:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.AbortTiming.Close.BeforeCommit",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_UNKNOWN_NAVIGATION:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.AbortTiming.UnknownNavigation."
+          "BeforeCommit",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_OTHER:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.AbortTiming.Other.BeforeCommit",
+          time_to_abort);
+      break;
+    default:
+      break;
+  }
+}
+
+void LogProvisionalAbortsUsingOpener(UserAbortType abort_type,
+                                       base::TimeDelta time_to_abort) {
+  switch (abort_type) {
+    case UserAbortType::ABORT_STOP:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.Opener.AbortTiming.Stop.BeforeCommit",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_CLOSE:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.Opener.AbortTiming.Close.BeforeCommit",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_UNKNOWN_NAVIGATION:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.Opener.AbortTiming.UnknownNavigation."
+          "BeforeCommit",
+          time_to_abort);
+      break;
+    case UserAbortType::ABORT_OTHER:
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Clients.FromGWS2.Opener.AbortTiming.Other.BeforeCommit",
+          time_to_abort);
+      break;
+    default:
+      break;
+  }
+}
+
+void LogPerformanceMetrics(
+    const page_load_metrics::PageLoadTiming& timing,
+    const page_load_metrics::PageLoadExtraInfo& extra_info) {
+  if (WasStartedInForegroundEventInForeground(
+          timing.dom_content_loaded_event_start, extra_info)) {
+    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSDomContentLoaded,
+                        timing.dom_content_loaded_event_start);
+  }
+  if (WasStartedInForegroundEventInForeground(timing.parse_stop, extra_info)) {
+    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSParseDuration,
+                        timing.parse_stop - timing.parse_start);
+  }
+  if (WasStartedInForegroundEventInForeground(timing.load_event_start,
+                                              extra_info)) {
+    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSLoad,
+                        timing.load_event_start);
+  }
+  if (WasStartedInForegroundEventInForeground(timing.first_text_paint,
+                                              extra_info)) {
+    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSFirstTextPaint,
+                        timing.first_text_paint);
+  }
+  if (WasStartedInForegroundEventInForeground(timing.first_image_paint,
+                                              extra_info)) {
+    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSFirstImagePaint,
+                        timing.first_image_paint);
+  }
+  if (WasStartedInForegroundEventInForeground(timing.first_paint, extra_info)) {
+    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSFirstPaint,
+                        timing.first_paint);
+  }
+  if (WasStartedInForegroundEventInForeground(timing.first_contentful_paint,
+                                              extra_info)) {
+    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSFirstContentfulPaint,
+                        timing.first_contentful_paint);
+
+    // If we have a foreground paint, we should have a foreground parse start,
+    // since paints can't happen until after parsing starts.
+    DCHECK(WasStartedInForegroundEventInForeground(timing.parse_start,
+                                                   extra_info));
+    PAGE_LOAD_HISTOGRAM(
+        internal::kHistogramFromGWSParseStartToFirstContentfulPaint,
+        timing.first_contentful_paint - timing.parse_start);
+  }
+}
+
+void LogPerformanceMetricsUsingOpener(
+    const page_load_metrics::PageLoadTiming& timing,
+    const page_load_metrics::PageLoadExtraInfo& extra_info) {
+  if (WasStartedInForegroundEventInForeground(timing.first_contentful_paint,
+                                              extra_info)) {
+    PAGE_LOAD_HISTOGRAM(
+        "PageLoad.Clients.FromGWS2.Opener.NavigationToFirstContentfulPaint",
+        timing.first_contentful_paint);
+  }
+}
+
+}  // namespace
+
 // See
 // https://docs.google.com/document/d/1jNPZ6Aeh0KV6umw1yZrrkfXRfxWNruwu7FELLx_cpOg/edit
 // for additional details.
@@ -166,12 +361,26 @@ bool FromGWSPageLoadMetricsLogger::QueryContainsComponentHelper(
   return false;
 }
 
+void FromGWSPageLoadMetricsLogger::SetPreviouslyCommittedUrl(const GURL& url) {
+  previously_committed_url_from_gws_ = IsUrlFromGWS(url);
+  previously_committed_url_from_redirector_ = IsGoogleSearchRedirectorUrl(url);
+}
+
+void FromGWSPageLoadMetricsLogger::SetOpenerUrl(const GURL& url) {
+  opener_from_gws_ = IsUrlFromGWS(url);
+}
+
 FromGWSPageLoadMetricsObserver::FromGWSPageLoadMetricsObserver() {}
 
 void FromGWSPageLoadMetricsObserver::OnStart(
     content::NavigationHandle* navigation_handle,
+    content::WebContents* web_contents,
     const GURL& currently_committed_url) {
-  logger_.set_previously_committed_url(currently_committed_url);
+  logger_.SetPreviouslyCommittedUrl(currently_committed_url);
+  DCHECK(web_contents);
+  if (web_contents->GetOpener()) {

[Bryan McQuade, 2016/04/21 20:50:41]

one concern i have is if the current tab doesn't have a committed url we will
fall back to the opener even if other navigations have occurred in this tab,
which doesn't seem like what we want.

an alternative would be to treat the last committed url of the opener as the
previously committed url for the first PageLoadTracker instantiated in each
MetricsWebContentsObserver (the first navigation in the tab), in cases where
there is an opener. so we'd basically be moving this logic into MWCO. this seems
conceptually consistent with the intent of providing a previously committed url
and reduces the complexity of PLMObservers. we might need to update the comments
for previously_committed_url slightly to explain this change in logic. the only
drawback here is that observers can no longer distinguish between these cases,
but i'm not sure i expect that they'll have a need to. what do you think?

[Charlie Harrison, 2016/04/21 21:09:24]

Agreed that's a better approach.

+    logger_.SetOpenerUrl(web_contents->GetOpener()->GetLastCommittedURL());
+  }
 }
 
 void FromGWSPageLoadMetricsObserver::OnCommit(
@@ -182,6 +391,9 @@ void FromGWSPageLoadMetricsObserver::OnCommit(
                                    ui::PAGE_TRANSITION_LINK));
 }
 
+void FromGWSPageLoadMetricsObserver::OnFailedProvisionalLoad(
+    content::NavigationHandle* navigation_handle) {}
+
 void FromGWSPageLoadMetricsObserver::OnComplete(
     const page_load_metrics::PageLoadTiming& timing,
     const page_load_metrics::PageLoadExtraInfo& extra_info) {
@@ -191,80 +403,94 @@ void FromGWSPageLoadMetricsObserver::OnComplete(
 void FromGWSPageLoadMetricsLogger::OnComplete(
     const page_load_metrics::PageLoadTiming& timing,
     const page_load_metrics::PageLoadExtraInfo& extra_info) {
-  if (ShouldLogMetrics(extra_info.committed_url)) {
-    LogMetrics(timing, extra_info);
+  internal::NavigationFromGWSType navigation_type =

[Bryan McQuade, 2016/04/21 20:50:41]

if navigation_type ends up returning NavigationNotFromGWS can we just return
early and avoid doing any of the work below?

[Charlie Harrison, 2016/04/21 21:09:24]

Yep.

+      GetNavigationFromGWSType(extra_info.committed_url);
+
+  UserAbortType abort_type = extra_info.abort_type;
+  base::TimeDelta time_to_abort = extra_info.time_to_abort;
+
+  // Consider this a foregrounded abort if it occurred within 100ms of a
+  // background. This is needed for closing some tabs, where the signal for
+  // background is often slightly ahead of the signal for close.

[Bryan McQuade, 2016/04/21 20:50:41]

interesting - is this due to recording some timings in the render process and
some in the browser process, or is there just an inherent race here?

[Charlie Harrison, 2016/04/21 21:09:24]

I think there's an inherent race with the WebContents destructor. This may have
something to do with the problems with Close on Android, but I couldn't figure
that one out today.

+  float bg_abort_delta =
+      (time_to_abort - extra_info.first_background_time).InMillisecondsF();
+  bool foregrounded =

[Bryan McQuade, 2016/04/21 20:50:41]

can we factor this bit of logic into a static helper method, something like

bool WasAbortedInForeground(...) {
if (time_to_abort.is_zero())
  return false;
if (abort_type == ABORT_NONE)
  return false;
if (WasStartedInForegroundEventInForeground(time_to_abort, extra_info)
  return true;
DCHECK(time_to_abort > extra_info.first_background_time);
// Consider this a foregrounded abort if it occurred within 100ms of...
TimeDelta bg_abort_delta = time_to_abort - extra_info.first_background_time;
if (bg_abort_delta.InMillisecondsF() <= 100)
  return true;
return false;
}

something like that anyway.

[Charlie Harrison, 2016/04/21 21:09:24]

Acknowledged.

+      WasStartedInForegroundEventInForeground(time_to_abort, extra_info) ||
+      bg_abort_delta <= 100;
+  bool aborted = abort_type != UserAbortType::ABORT_NONE && foregrounded &&
+                 !time_to_abort.is_zero();
+  // If we have a committed load but |timing.IsEmpty()|, then this load was not
+  // tracked by the renderer. In this case, it is not possible to know whether
+  // the abort signals came before the page painted. Additionally, for
+  // consistency with PageLoad.Timing2 metrics, we ignore non-render-tracked
+  // loads when tracking aborts after commit.
+  bool aborted_before_paint =
+      aborted && !timing.IsEmpty() &&
+      (timing.first_paint.is_zero() || timing.first_paint >= time_to_abort);
+
+  switch (navigation_type) {
+    case internal::CommittedNavigationFromGWSPreviousCommit:
+      LogPerformanceMetrics(timing, extra_info);
+      if (aborted_before_paint)
+        LogCommittedAborts(abort_type, time_to_abort);
+      break;
+    case internal::CommittedNavigationFromGWSOpener:
+      LogPerformanceMetricsUsingOpener(timing, extra_info);
+      if (aborted_before_paint)
+        LogCommittedAbortsUsingOpener(abort_type, time_to_abort);
+      break;
+    case internal::ProvisionalNavigationFromGWSPreviousCommit:
+      if (aborted)
+        LogProvisionalAborts(abort_type, time_to_abort);
+      break;
+    case internal::ProvisionalNavigationFromGWSOpener:
+      if (aborted)
+        LogProvisionalAbortsUsingOpener(abort_type, time_to_abort);
+      break;
+    case internal::NavigationNotFromGWS:
+      break;
   }
 }
 
-bool FromGWSPageLoadMetricsLogger::ShouldLogMetrics(
+internal::NavigationFromGWSType
+FromGWSPageLoadMetricsLogger::GetNavigationFromGWSType(
     const GURL& committed_url) const {
-  // If we didn't navigate from another page, then this couldn't be a navigation
-  // from search, so don't log stats.
-  if (previously_committed_url_.is_empty())
-    return false;
-
-  // If this navigation didn't commit, or this page is a known google redirector
-  // URL or Google search results URL, then we should not log stats.
-  if (committed_url.is_empty() || IsGoogleRedirectorUrl(committed_url) ||
-      IsGoogleSearchResultUrl(committed_url))
-    return false;
-
-  // We're only interested in tracking user gesture initiated navigations
-  // (e.g. clicks) initiated via links.
-  if (!navigation_initiated_via_link_)
-    return false;
+  // If this page is a known google redirector URL or Google search results URL,
+  // then we should not log stats.
+  if (IsUrlFromGWS(committed_url))
+    return internal::NavigationNotFromGWS;

[Bryan McQuade, 2016/04/21 20:50:41]

this ends up implementing the policy we want but it doesn't feel like this logic
belongs in this method. can we instead check IsUrlFromGWS() at the call site to
GetNavigationFromGWSType and if that method returns true there, don't even
continue past that point?

[Charlie Harrison, 2016/04/21 21:09:24]

SGTM.

+
+  bool committed = !committed_url.is_empty();
+  if (committed) {
+    // We're only interested in tracking user gesture initiated navigations
+    // (e.g. clicks) initiated via links. Note that the redirector will mask
+    // these, so don't enforce this if the navigation came from a redirect url.
+    // TODO(csharrison): Use this signal for provisional loads when the content
+    // APIs allow for it.
+    if (!navigation_initiated_via_link_ &&
+        !previously_committed_url_from_redirector_) {
+      return internal::NavigationNotFromGWS;
+    }
 
-  // We're only interested in navigations from the SRP or through the JS
-  // redirector.
-  if (!IsGoogleSearchResultUrl(previously_committed_url_) &&
-      !IsGoogleSearchRedirectorUrl(previously_committed_url_))
-    return false;
+    if (previously_committed_url_from_gws_) {
+      return internal::CommittedNavigationFromGWSPreviousCommit;
+    } else if (opener_from_gws_) {
+      return internal::CommittedNavigationFromGWSOpener;
+    }
+  } else {  // !committed
+    if (previously_committed_url_from_gws_) {
+      return internal::ProvisionalNavigationFromGWSPreviousCommit;
+    } else if (opener_from_gws_) {
+      return internal::ProvisionalNavigationFromGWSOpener;
+    }
+  }
+  return internal::NavigationNotFromGWS;
+}
 
-  return true;
+// We're only interested in navigations from the SRP or through the JS
+// redirector.
+bool FromGWSPageLoadMetricsLogger::IsUrlFromGWS(const GURL& url) {
+  return IsGoogleSearchResultUrl(url) || IsGoogleSearchRedirectorUrl(url);
 }
 
-void FromGWSPageLoadMetricsLogger::LogMetrics(
-    const page_load_metrics::PageLoadTiming& timing,
-    const page_load_metrics::PageLoadExtraInfo& extra_info) {
-  if (WasStartedInForegroundEventInForeground(
-          timing.dom_content_loaded_event_start, extra_info)) {
-    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSDomContentLoaded,
-                        timing.dom_content_loaded_event_start);
-  }
-  if (WasStartedInForegroundEventInForeground(timing.parse_stop, extra_info)) {
-    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSParseDuration,
-                        timing.parse_stop - timing.parse_start);
-  }
-  if (WasStartedInForegroundEventInForeground(timing.load_event_start,
-                                              extra_info)) {
-    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSLoad,
-                        timing.load_event_start);
-  }
-  if (WasStartedInForegroundEventInForeground(timing.first_text_paint,
-                                              extra_info)) {
-    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSFirstTextPaint,
-                        timing.first_text_paint);
-  }
-  if (WasStartedInForegroundEventInForeground(timing.first_image_paint,
-                                              extra_info)) {
-    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSFirstImagePaint,
-                        timing.first_image_paint);
-  }
-  if (WasStartedInForegroundEventInForeground(timing.first_paint, extra_info)) {
-    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSFirstPaint,
-                        timing.first_paint);
-  }
-  if (WasStartedInForegroundEventInForeground(timing.first_contentful_paint,
-                                              extra_info)) {
-    PAGE_LOAD_HISTOGRAM(internal::kHistogramFromGWSFirstContentfulPaint,
-                        timing.first_contentful_paint);
 
-    // If we have a foreground paint, we should have a foreground parse start,
-    // since paints can't happen until after parsing starts.
-    DCHECK(WasStartedInForegroundEventInForeground(timing.parse_start,
-                                                   extra_info));
-    PAGE_LOAD_HISTOGRAM(
-        internal::kHistogramFromGWSParseStartToFirstContentfulPaint,
-        timing.first_contentful_paint - timing.parse_start);
-  }
-}