[do not review][page_load_metrics] User Initiated Abort Tracking

components/page_load_metrics/browser/metrics_web_contents_observer.cc

Index: components/page_load_metrics/browser/metrics_web_contents_observer.cc
diff --git a/components/page_load_metrics/browser/metrics_web_contents_observer.cc b/components/page_load_metrics/browser/metrics_web_contents_observer.cc
index ffda133e4e271b6097821cd67b1a55824f25e78a..bfb0dc6d15bbfcdc192124df40874fac661afe45 100644
--- a/components/page_load_metrics/browser/metrics_web_contents_observer.cc
+++ b/components/page_load_metrics/browser/metrics_web_contents_observer.cc
@@ -22,6 +22,7 @@
 #include "content/public/browser/web_contents_user_data.h"
 #include "ipc/ipc_message.h"
 #include "ipc/ipc_message_macros.h"
+#include "ui/base/page_transition_types.h"
 
 DEFINE_WEB_CONTENTS_USER_DATA_KEY(
     page_load_metrics::MetricsWebContentsObserver);
@@ -81,6 +82,15 @@ void RecordInternalError(InternalErrorLoadEvent event) {
   UMA_HISTOGRAM_ENUMERATION(kErrorEvents, event, ERR_LAST_ENTRY);
 }
 
+UserAbortType AbortTypeForPageTransition(ui::PageTransition transition) {
+  if (ui::PageTransitionCoreTypeIs(transition, ui::PAGE_TRANSITION_RELOAD))

[Bryan McQuade, 2015/11/23 22:39:44]

any reason we use PageTransitionCoreTypeIs here but not in the 'else if' below?

[Charlie Harrison, 2015/11/25 20:15:25]

PAGE_TRANSITION_FORWARD_BACK is a qualifier, not a core type.

+    return ABORT_RELOAD;
+  else if (transition & ui::PAGE_TRANSITION_FORWARD_BACK)
+    return ABORT_FORWARD_BACK;
+  else
+    return ABORT_NEW_NAVIGATION;
+}
+
 base::TimeDelta GetFirstContentfulPaint(const PageLoadTiming& timing) {
   if (timing.first_text_paint.is_zero())
     return timing.first_image_paint;
@@ -121,6 +131,7 @@ PageLoadTracker::PageLoadTracker(
     base::ObserverList<PageLoadMetricsObserver, true>* observers)
     : has_commit_(false),
       navigation_start_(navigation_handle->NavigationStart()),
+      abort_type_(ABORT_NONE),
       started_in_foreground_(in_foreground),
       embedder_interface_(embedder_interface),
       observers_(observers) {}
@@ -130,6 +141,7 @@ PageLoadTracker::~PageLoadTracker() {
     RecordTimingHistograms();
     RecordRappor();
   }
+  RecordAbortTimingHistograms();
 }
 
 void PageLoadTracker::WebContentsHidden() {
@@ -184,14 +196,79 @@ bool PageLoadTracker::HasBackgrounded() {
 PageLoadExtraInfo PageLoadTracker::GetPageLoadMetricsInfo() {
   base::TimeDelta first_background_time;
   base::TimeDelta first_foreground_time;
-  if (!background_time_.is_null() && started_in_foreground_)
+  if (!background_time_.is_null())
     first_background_time = background_time_ - navigation_start_;
-  if (!foreground_time_.is_null() && !started_in_foreground_)
+  if (!foreground_time_.is_null())
     first_foreground_time = foreground_time_ - navigation_start_;
   return PageLoadExtraInfo(first_background_time, first_foreground_time,
                            started_in_foreground_);
 }
 
+// We consider the first abort passed here as the true abort, unless it is
+// ABORT_OTHER, so call this with decreasing specificity.
+void PageLoadTracker::NotifyAbort(UserAbortType abort_type,
+                                  const base::TimeTicks& timestamp) {
+  DCHECK(abort_type != ABORT_NONE);
+  if (abort_type_ == ABORT_NONE) {
+    abort_type_ = abort_type;
+    abort_time_ = timestamp;
+  }
+
+  // If we got a better signal than ABORT_OTHER in the last 100ms, treat it
+  // as the cause of the abort (Some ABORT_OTHER signals occur before the true
+  // signal). Note that this only occurs for provisional loads. While this
+  // heuristic is coarse, it works better and is simpler than other feasible
+  // methods.

[Bryan McQuade, 2015/11/23 22:39:44]

Let's link to your design doc here so people reading the code can get more
insight on why the 100ms threshold is the best overall option, given the
complexity tradeoffs.

[Charlie Harrison, 2015/11/25 20:15:25]

Done.

+  if (abort_type_ == ABORT_OTHER && abort_type != ABORT_OTHER
+      && (timestamp - abort_time_).InMillisecondsF() < 100) {
+    abort_type_ = abort_type;
+    abort_time_ = std::min(abort_time_, timestamp);

[Bryan McQuade, 2015/11/23 22:39:44]

do we ever expect timestamp to be less than abort_time_? on first glance that
seems like it should never happen. if you don't expect it, i'd rather do:

DCHECK_LE(abort_time_, timestamp);
abort_time_ = timestamp;

[Charlie Harrison, 2015/11/25 20:15:25]

I think it is possible. For instance if we get an ABORT_OTHER which gets
replaced by a navigation start. We always want the earliest value.

+  }
+}
+
+void PageLoadTracker::RecordAbortTimingHistograms() {
+  if (abort_type_ == ABORT_NONE)
+    return;
+  DCHECK(!abort_time_.is_null());
+
+  // Loads are not considered aborts if they painted before the abort event.
+  base::TimeDelta time_to_abort = abort_time_ - navigation_start_;
+  if (!timing_.first_paint.is_zero() && timing_.first_paint < time_to_abort)
+    return;
+
+  // Don't log abort times if the page was backgrounded before the abort event.
+  if (GetBackgroundDelta() < time_to_abort)
+    return;
+  if (has_commit_) {
+    if (abort_type_ == ABORT_RELOAD) {
+      PAGE_LOAD_HISTOGRAM(kHistogramCommittedAbortReload, time_to_abort);
+    } else if (abort_type_ == ABORT_FORWARD_BACK) {
+      PAGE_LOAD_HISTOGRAM(kHistogramCommittedAbortForwardBack, time_to_abort);
+    } else if (abort_type_ == ABORT_NEW_NAVIGATION) {
+      PAGE_LOAD_HISTOGRAM(kHistogramCommittedAbortNewNavigation, time_to_abort);
+    } else if (abort_type_ == ABORT_STOP) {
+      PAGE_LOAD_HISTOGRAM(kHistogramCommittedAbortStop, time_to_abort);
+    } else if (abort_type_ == ABORT_CLOSE) {
+      PAGE_LOAD_HISTOGRAM(kHistogramCommittedAbortClose, time_to_abort);
+    }

[Bryan McQuade, 2015/11/23 21:33:42]

can we add:
else {
DLOG(FATAL) << "Received ABORT_OTHER for committed load.";
}

[Charlie Harrison, 2015/11/25 20:15:25]

Done.

+  } else {
+    if (abort_type_ == ABORT_RELOAD) {
+      PAGE_LOAD_HISTOGRAM(kHistogramProvisionalAbortReload, time_to_abort);
+    } else if (abort_type_ == ABORT_FORWARD_BACK) {
+      PAGE_LOAD_HISTOGRAM(kHistogramProvisionalAbortForwardBack, time_to_abort);
+    } else if (abort_type_ == ABORT_NEW_NAVIGATION) {
+      PAGE_LOAD_HISTOGRAM(kHistogramProvisionalAbortNewNavigation,
+                          time_to_abort);
+    } else if (abort_type_ == ABORT_STOP) {
+      PAGE_LOAD_HISTOGRAM(kHistogramProvisionalAbortStop, time_to_abort);
+    } else if (abort_type_ == ABORT_CLOSE) {
+      PAGE_LOAD_HISTOGRAM(kHistogramProvisionalAbortClose, time_to_abort);
+    } else if (abort_type_ == ABORT_OTHER) {
+      PAGE_LOAD_HISTOGRAM(kHistogramProvisionalAbortOther, time_to_abort);
+    }
+  }
+}
+
 const GURL& PageLoadTracker::GetCommittedURL() {
   DCHECK(has_commit_);
   return url_;
@@ -219,6 +296,16 @@ base::TimeDelta PageLoadTracker::GetBackgroundDelta() {
 
 void PageLoadTracker::RecordTimingHistograms() {
   DCHECK(has_commit_);
+  base::TimeDelta background_delta = GetBackgroundDelta();
+  if (!background_time_.is_null() && (timing_.first_paint.is_zero() ||
+                                      background_delta < timing_.first_paint)) {
+    PAGE_LOAD_HISTOGRAM(kHistogramBackgroundBeforePaint,
+                        background_time_ - navigation_start_);
+  }
+
+  // The rest of the timing histograms require us to have received IPCs from the
+  // renderer. Record UMA for how often this occurs (usually for quickly aborted
+  // loads). For now, don't update observers if this is the case.
   if (timing_.IsEmpty()) {
     RecordInternalError(ERR_NO_IPCS_RECEIVED);
     return;
@@ -228,8 +315,6 @@ void PageLoadTracker::RecordTimingHistograms() {
   FOR_EACH_OBSERVER(PageLoadMetricsObserver, *observers_,
                     OnComplete(timing_, info));
 
-  base::TimeDelta background_delta = GetBackgroundDelta();
-
   if (!timing_.dom_content_loaded_event_start.is_zero()) {
     if (timing_.dom_content_loaded_event_start < background_delta) {
       PAGE_LOAD_HISTOGRAM(kHistogramDomContentLoaded,
@@ -376,8 +461,10 @@ MetricsWebContentsObserver* MetricsWebContentsObserver::CreateForWebContents(
 
 MetricsWebContentsObserver::~MetricsWebContentsObserver() {
   // Reset PageLoadTrackers so observers get final notifications.
+  NotifyAbortAllLoads(ABORT_CLOSE);
   committed_load_.reset();
   provisional_loads_.clear();
+  aborted_provisional_loads_.clear();
   FOR_EACH_OBSERVER(PageLoadMetricsObserver, observers_,
                     OnPageLoadMetricsGoingAway());
 }
@@ -439,12 +526,18 @@ void MetricsWebContentsObserver::DidFinishNavigation(
   // Handle a pre-commit error here. Navigations that result in an error page
   // will be ignored. Note that downloads/204s will result in HasCommitted()
   // returning false.
+  // TODO(csharrison): Track changes to NavigationHandle for signals when this
+  // is the case (HTTP response headers).
   if (!navigation_handle->HasCommitted()) {
     net::Error error = navigation_handle->GetNetErrorCode();
-    finished_nav->RecordProvisionalEvent(
-        error == net::OK ? PROVISIONAL_LOAD_STOPPED
+    ProvisionalLoadEvent event = error == net::OK ? PROVISIONAL_LOAD_STOPPED
         : error == net::ERR_ABORTED ? PROVISIONAL_LOAD_ERR_ABORTED
-        : PROVISIONAL_LOAD_ERR_FAILED_NON_ABORT);
+        : PROVISIONAL_LOAD_ERR_FAILED_NON_ABORT;
+    finished_nav->RecordProvisionalEvent(event);
+    if (event != PROVISIONAL_LOAD_ERR_FAILED_NON_ABORT) {

[Bryan McQuade, 2015/11/23 22:39:44]

if event == PROVISIONAL_LOAD_STOPPED, should we pass ABORT_STOP to NotifyAbort?
or does PROVISIONAL_LOAD_STOPPED have a slightly different meaning than the STOP
in ABORT_STOP (in which case is there a better name we should use instead of
PROVISIONAL_LOAD_STOPPED)?

[Charlie Harrison, 2015/11/25 20:15:25]

I think it should represent stop, but I'm not fully sure. Right now they
supposedly should not be occuring but we're still seeing some samples. I think
best to be safe for now and we can continue investigating.

+      finished_nav->NotifyAbort(ABORT_OTHER, base::TimeTicks::Now());
+      aborted_provisional_loads_.push_back(finished_nav.Pass());
+    }
     return;
   }
   finished_nav->RecordProvisionalEvent(PROVISIONAL_LOAD_COMMITTED);
@@ -453,9 +546,19 @@ void MetricsWebContentsObserver::DidFinishNavigation(
   if (navigation_handle->IsSamePage())
     return;
 
+  // Notify other loads that they may have been aborted by this committed load.
+  // Note that by using the committed navigation start as the abort cause, we
+  // lose data on provisional loads that were aborted by other provisional
+  // loads. Those will either be listed as ABORT_OTHER or as being aborted by
+  // this load.
+  NotifyAbortAllLoadsWithTimestamp(
+      AbortTypeForPageTransition(navigation_handle->GetPageTransition()),
+      navigation_handle->NavigationStart());
+
   // Eagerly log the previous UMA even if we don't care about the current
   // navigation.
   committed_load_.reset();
+  aborted_provisional_loads_.clear();
 
   const GURL& browser_url = web_contents()->GetLastCommittedURL();
   const std::string& mime_type = web_contents()->GetContentsMimeType();
@@ -468,6 +571,10 @@ void MetricsWebContentsObserver::DidFinishNavigation(
   committed_load_->Commit(navigation_handle);
 }
 
+void MetricsWebContentsObserver::NavigationStopped() {
+  NotifyAbortAllLoads(ABORT_STOP);
+}
+
 void MetricsWebContentsObserver::DidRedirectNavigation(
     content::NavigationHandle* navigation_handle) {
   if (!navigation_handle->IsInMainFrame())
@@ -501,7 +608,27 @@ void MetricsWebContentsObserver::WasHidden() {
 // we have one.
 void MetricsWebContentsObserver::RenderProcessGone(
     base::TerminationStatus status) {
+  NotifyAbortAllLoads(ABORT_CLOSE);
   committed_load_.reset();
+  provisional_loads_.clear();
+  aborted_provisional_loads_.clear();
+}
+
+void MetricsWebContentsObserver::NotifyAbortAllLoads(UserAbortType abort_type) {
+  NotifyAbortAllLoadsWithTimestamp(abort_type, base::TimeTicks::Now());
+}
+
+void MetricsWebContentsObserver::NotifyAbortAllLoadsWithTimestamp(
+    UserAbortType abort_type,
+    const base::TimeTicks& timestamp) {
+  if (committed_load_)
+    committed_load_->NotifyAbort(abort_type, timestamp);
+  for (const auto& kv : provisional_loads_) {
+    kv.second->NotifyAbort(abort_type, timestamp);
+  }
+  for (const auto& plt : aborted_provisional_loads_) {
+    plt->NotifyAbort(abort_type, timestamp);
+  }
 }
 
 void MetricsWebContentsObserver::OnTimingUpdated(