[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 3e1db269cbc05761a974dd871614369af70141f7..b92ae7ba0f8eed69abbb98819226823a9e1d3a91 100644
--- a/components/page_load_metrics/browser/metrics_web_contents_observer.cc
+++ b/components/page_load_metrics/browser/metrics_web_contents_observer.cc
@@ -21,6 +21,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);
@@ -80,6 +81,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))
+    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;
@@ -120,6 +130,7 @@ PageLoadTracker::PageLoadTracker(
     base::ObserverList<PageLoadMetricsObserver, true>* observers)
     : has_commit_(false),
       navigation_start_(navigation_handle->navigation_start()),
+      abort_type_(ABORT_NULL),
       started_in_foreground_(in_foreground),
       embedder_interface_(embedder_interface),
       observers_(observers) {}
@@ -129,6 +140,7 @@ PageLoadTracker::~PageLoadTracker() {
     RecordTimingHistograms();
     RecordRappor();
   }
+  RecordAbortTimingHistograms();
 }
 
 void PageLoadTracker::WebContentsHidden() {
@@ -178,14 +190,90 @@ 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_NULL);
+  if (abort_type_ == ABORT_NULL) {
+    abort_type_ = abort_type;
+    abort_time_ = timestamp;
+  }
+
+  // If we got a better signal than ABORT_OTHER since the last navigation, 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.
+  if (abort_type_ == ABORT_OTHER && abort_type != ABORT_OTHER) {
+    abort_type_ = abort_type;
+    abort_time_ = std::min(abort_time_, timestamp);
+  }
+}
+
+void PageLoadTracker::RecordAbortTimingHistograms() {
+  // Log the background "abort" if we backgrounded a foregrounded page before
+  // its first paint. This is a slightly different notion of abort (we can still
+  // get to the first paint later), but it is still worthwhile measure.
+  if (!background_time_.is_null() &&
+      (timing_.first_paint.is_zero() ||
+       GetBackgroundDelta() < timing_.first_paint)) {
+    if (has_commit_) {
+      PAGE_LOAD_HISTOGRAM(kHistogramCommittedAbortBackground,

[Bryan McQuade, 2015/11/17 13:33:08]

this does feel like a user-initiated abort, but i worry that since it's
different from the typical definition of an aborted load, consumers of this in
the UMA dash might misinterpret it. maybe it's better to call this a 'background
before first paint' and not mix the abort concept in here. wdyt? if we do that,
seems like this might be better logged in RecordTimingHistograms as e.g.
PageLoad.Timing2.NavigationToFirstBackgroundBeforePaint

[Charlie Harrison, 2015/11/17 16:11:54]

I could go either way. I only put it here because it got brought up multiple
times in reference to user abort discussions. Moving it sgtm. Note that this
will end up tracking only committed, relevant loads. I think that's fine.

+                          background_time_ - navigation_start_);
+    } else {
+      PAGE_LOAD_HISTOGRAM(kHistogramProvisionalAbortBackground,
+                          background_time_ - navigation_start_);
+    }
+  }
+  if (abort_type_ == ABORT_NULL)
+    return;
+  DCHECK(!abort_time_.is_null());
+
+  // Loads are not considered aborts if they painted before the abort event.

[Bryan McQuade, 2015/11/17 13:33:08]

i'm inclined to either ignore aborts when a tab is backgrounded, or if you think
tracking time-to-abort for backgrounded tabs is useful, separating them into
'.background'-suffixed histograms.

[Charlie Harrison, 2015/11/17 16:11:54]

I'm inclined to ignore them for now and add later if we feel we need them. Good
catch. Done.

+  base::TimeDelta time_to_abort = abort_time_ - navigation_start_;
+  if (!timing_.first_paint.is_zero() && timing_.first_paint < 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);
+    } else if (abort_type_ == ABORT_OTHER) {
+      PAGE_LOAD_HISTOGRAM(kHistogramCommittedAbortOther, time_to_abort);
+    }
+  } 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_;
@@ -370,8 +458,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());
 }
@@ -433,12 +523,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

[Bryan McQuade, 2015/11/17 13:33:08]

IIRC downloads/204s report ERR_ABORTED, so we'll end up counting them as aborts
currently. I like your TODO above - wondering if it's important for us to fix it
so we can differentiate these cases. I guess as-is we can at least know that
these aborts will end up in the 'other' category and we can look at it with
skepticism for now. Still though I worry about consumers of this data not
understanding the subtleties and drawing incorrect conclusions.

[Charlie Harrison, 2015/11/17 16:11:54]

Let's see. It's possible clamy@ will land her change before this one.

-        : PROVISIONAL_LOAD_ERR_FAILED_NON_ABORT);
+        : PROVISIONAL_LOAD_ERR_FAILED_NON_ABORT;
+    finished_nav->RecordProvisionalEvent(event);
+    if (event != PROVISIONAL_LOAD_ERR_FAILED_NON_ABORT) {
+      finished_nav->NotifyAbort(ABORT_OTHER, base::TimeTicks::Now());
+      aborted_provisional_loads_.push_back(finished_nav.Pass());

[Bryan McQuade, 2015/11/17 13:33:08]

the aborted_provisional_loads_ member makes me a bit uneasy. seems like we hold
on to these in order to find a possibly more accurate abort reason in the
future. but it also seems like we could end up attributing the wrong abort
reason in some cases. for example, imagine we get a 204 response which leads to
an ERR_ABORTED, which we classify here as ABORT_OTHER. Then many seconds in the
future, before the next nav commits (perhaps the user just never navigates
again), the user closes the tab and the destructor runs, causing us to update
the abort type to ABORT_CLOSE with the abort timestamp from when the 204
completed. This seems incorrect to me - the 'close' event was not really
associated with the 204 that happened a bit in the past. It seems like there is
a good bit of complexity here though, and your solution may be the best we can
do given the constraints, but I'd like to talk things through to see if there
are any simplifications we can make.

+    }
     return;
   }
   finished_nav->RecordProvisionalEvent(PROVISIONAL_LOAD_COMMITTED);

[Bryan McQuade, 2015/11/17 13:33:08]

just noticing now - unrelated to this change - should this call to record a
PROVISIONAL_LOAD_COMMITTED event be after the IsSamePage check below? I seem to
remember feeling this was correct at the time it was added but now I'm not sure.
This is not something we need to fix in this CL - but just want to make sure it
doesn't get overlooked.

[Charlie Harrison, 2015/11/17 16:11:54]

This was intentional. If we want we can break up the provisional loads into
another class (same-page). This was done so all the provisional events add up.

@@ -447,6 +543,11 @@ void MetricsWebContentsObserver::DidFinishNavigation(
   if (navigation_handle->IsSamePage())
     return;
 
+  // Notify other loads that they may have been aborted by this committed load
+  NotifyAbortAllLoadsWithTimestamp(
+      AbortTypeForPageTransition(navigation_handle->GetPageTransition()),
+      navigation_handle->navigation_start());
+
   // Eagerly log the previous UMA even if we don't care about the current
   // navigation.
   committed_load_.reset();
@@ -460,6 +561,11 @@ void MetricsWebContentsObserver::DidFinishNavigation(
 
   committed_load_ = finished_nav.Pass();
   committed_load_->Commit(navigation_handle);
+  aborted_provisional_loads_.clear();

[Bryan McQuade, 2015/11/17 13:33:08]

should we clear aborted_provisional_loads_ even if IsRelevantNavigation returns
false? should this be moved further up, near committed_load_.reset()?

[Charlie Harrison, 2015/11/17 16:11:54]

Yupp good idea. Done.

+}
+
+void MetricsWebContentsObserver::NavigationStopped() {
+  NotifyAbortAllLoads(ABORT_STOP);
 }
 
 void MetricsWebContentsObserver::WasShown() {
@@ -485,7 +591,26 @@ 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(