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

components/page_load_metrics/browser/metrics_web_contents_observer.cc

 // Copyright 2015 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "components/page_load_metrics/browser/metrics_web_contents_observer.h"
 
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/metrics/histogram.h"
 #include "components/page_load_metrics/browser/page_load_metrics_macros.h"
 #include "components/page_load_metrics/common/page_load_metrics_messages.h"
 #include "components/page_load_metrics/common/page_load_timing.h"
 #include "components/rappor/rappor_service.h"
 #include "components/rappor/rappor_utils.h"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/navigation_details.h"
 #include "content/public/browser/navigation_handle.h"
 #include "content/public/browser/render_frame_host.h"
 #include "content/public/browser/web_contents.h"
 #include "content/public/browser/web_contents_observer.h"
 #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);
 
 namespace page_load_metrics {
 
 namespace {
 
 // The url we see from the renderer side is not always the same as what
 // we see from the browser side (e.g. chrome://newtab). We want to be
@@ skipping 39 matching lines @@
     return false;
   }
 
   return true;
 }
 
 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;
   if (timing.first_image_paint.is_zero())
     return timing.first_text_paint;
   return std::min(timing.first_text_paint, timing.first_image_paint);
 }
 
 // The number of buckets in the bitfield histogram. These buckets are described
 // in rappor.xml in PageLoad.CoarseTiming.NavigationToFirstContentfulPaint.
@@ skipping 20 matching lines @@
 
 }  // namespace
 
 PageLoadTracker::PageLoadTracker(
     bool in_foreground,
     PageLoadMetricsEmbedderInterface* embedder_interface,
     content::NavigationHandle* navigation_handle,
     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) {}
 
 PageLoadTracker::~PageLoadTracker() {
   if (has_commit_) {
     RecordTimingHistograms();
     RecordRappor();
   }
+  RecordAbortTimingHistograms();
 }
 
 void PageLoadTracker::WebContentsHidden() {
   // Only log the first time we background in a given page load.
   if (started_in_foreground_ && background_time_.is_null())
     background_time_ = base::TimeTicks::Now();
 }
 
 void PageLoadTracker::WebContentsShown() {
   // Only log the first time we foreground in a given page load.
@@ skipping 29 matching lines @@
   return false;
 }
 
 bool PageLoadTracker::HasBackgrounded() {
   return !started_in_foreground_ || !background_time_.is_null();
 }
 
 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_;
 }
 
 // Blink calculates navigation start using TimeTicks, but converts to epoch time
 // in its public API. Thus, to compare time values to navigation start, we
 // calculate the current time since the epoch using TimeTicks, and convert to
 // Time. This method is similar to how blink converts TimeTicks to epoch time.
 // There may be slight inaccuracies due to inter-process timestamps, but
@@ skipping 164 matching lines @@
   if (!metrics) {
     metrics =
         new MetricsWebContentsObserver(web_contents, embedder_interface.Pass());
     web_contents->SetUserData(UserDataKey(), metrics);
   }
   return metrics;
 }
 
 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());
 }
 
 void MetricsWebContentsObserver::AddObserver(
     PageLoadMetricsObserver* observer) {
   observers_.AddObserver(observer);
 }
 
 void MetricsWebContentsObserver::RemoveObserver(
@@ skipping 41 matching lines @@
   scoped_ptr<PageLoadTracker> finished_nav(
       provisional_loads_.take_and_erase(navigation_handle));
   // There's a chance a navigation could have started before we were added to a
   // tab. Bail out early if this is the case.
   if (!finished_nav)
     return;
 
   // 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.

 
   // Don't treat a same-page nav as a new page load.
   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();
 
   const GURL& browser_url = web_contents()->GetLastCommittedURL();
   const std::string& mime_type = web_contents()->GetContentsMimeType();
   DCHECK(!browser_url.is_empty());
   DCHECK(!mime_type.empty());
   if (!IsRelevantNavigation(navigation_handle, browser_url, mime_type))
     return;
 
   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() {
   in_foreground_ = true;
   if (committed_load_)
     committed_load_->WebContentsShown();
   for (const auto& kv : provisional_loads_) {
     kv.second->WebContentsShown();
   }
 }
 
 void MetricsWebContentsObserver::WasHidden() {
   in_foreground_ = false;
   if (committed_load_)
     committed_load_->WebContentsHidden();
   for (const auto& kv : provisional_loads_) {
     kv.second->WebContentsHidden();
   }
 }
 
 // This will occur when the process for the main RenderFrameHost exits, either
 // normally or from a crash. We eagerly log data from the last committed load if
 // 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(
     content::RenderFrameHost* render_frame_host,
     const PageLoadTiming& timing) {
   bool error = false;
   if (!committed_load_) {
     RecordInternalError(ERR_IPC_WITH_NO_COMMITTED_LOAD);
     error = true;
   }
@@ skipping 18 matching lines @@
 
   if (!committed_load_->UpdateTiming(timing)) {
     // If the page load tracker cannot update its timing, something is wrong
     // with the IPC (it's from another load, or it's invalid in some other way).
     // We expect this to be a rare occurrence.
     RecordInternalError(ERR_BAD_TIMING_IPC);
   }
 }
 
 }  // namespace page_load_metrics