[page_load_metrics] User Initiated Abort Tracking (Observer version)

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 "base/metrics/user_metrics.h"
 #include "components/page_load_metrics/browser/page_load_metrics_util.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;

[Bryan McQuade, 2015/12/10 21:21:14]

can we add a DCHECK(ui::PageTransitionIsNewNavigation(transition)); in the else
case just to be sure there aren't any surprising cases here?

or:
...
else if (ui::PageTransitionIsNewNavigation(transition))
  return ABORT_NEW_NAVIGATION;
NOTREACHED();
return ABORT_OTHER;

[Charlie Harrison, 2015/12/10 22:00:54]

Done.

+}
+
 // The number of buckets in the bitfield histogram. These buckets are described
 // in rappor.xml in PageLoad.CoarseTiming.NavigationToFirstContentfulPaint.
 // The bucket flag is defined by 1 << bucket_index, and is the bitfield
 // representing which timing bucket the page load falls into, i.e. 000010
 // would be the bucket flag showing that the page took between 2 and 4 seconds
 // to load.
 const size_t kNumRapporHistogramBuckets = 6;
 
 uint64_t RapporHistogramBucketIndex(const base::TimeDelta& time) {
   int64 seconds = time.InSeconds();
@@ skipping 12 matching lines @@
 
 }  // namespace
 
 PageLoadTracker::PageLoadTracker(
     bool in_foreground,
     PageLoadMetricsEmbedderInterface* embedder_interface,
     content::NavigationHandle* navigation_handle)
     : renderer_tracked_(false),
       has_commit_(false),
       navigation_start_(navigation_handle->NavigationStart()),
+      abort_type_(ABORT_NONE),
       started_in_foreground_(in_foreground),
       embedder_interface_(embedder_interface) {
   embedder_interface_->RegisterObservers(this);
   for (const auto& observer : observers_) {
     observer->OnStart(navigation_handle);
   }
 }
 
 PageLoadTracker::~PageLoadTracker() {
-  if (has_commit_) {
-    RecordTimingHistograms();
-    RecordRappor();
-  }
   PageLoadExtraInfo info = GetPageLoadMetricsInfo();
+  RecordRappor(info);
+  RecordTimingHistograms(info);
   for (const auto& observer : observers_) {
     observer->OnComplete(timing_, info);
   }
 }
 
 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();
 }
@@ skipping 49 matching lines @@
 }
 
 void PageLoadTracker::AddObserver(
     scoped_ptr<PageLoadMetricsObserver> observer) {
   observers_.push_back(std::move(observer));
 }
 
 PageLoadExtraInfo PageLoadTracker::GetPageLoadMetricsInfo() {
   base::TimeDelta first_background_time;
   base::TimeDelta first_foreground_time;
+  base::TimeDelta time_to_abort;
   if (!background_time_.is_null() && started_in_foreground_)
     first_background_time = background_time_ - navigation_start_;
   if (!foreground_time_.is_null() && !started_in_foreground_)
     first_foreground_time = foreground_time_ - navigation_start_;
+  if (abort_type_ != ABORT_NONE) {
+    DCHECK(!abort_time_.is_null());
+    time_to_abort = abort_time_ - navigation_start_;
+  }
   return PageLoadExtraInfo(first_background_time, first_foreground_time,
-                           started_in_foreground_, has_commit_);
+                           started_in_foreground_, has_commit_, abort_type_,
+                           time_to_abort);
 }
 
 const GURL& PageLoadTracker::committed_url() {
   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
-// this solution is the best we have right now.
-//
-// returns a TimeDelta which is
-//  - Infinity if we were never backgrounded
-//  - null (TimeDelta()) if we started backgrounded
-//  - elapsed time to first background if we started in the foreground and
-//    backgrounded.
-base::TimeDelta PageLoadTracker::GetBackgroundDelta() {
-  if (started_in_foreground_) {
-    return background_time_.is_null() ? base::TimeDelta::Max()
-                                      : background_time_ - navigation_start_;
-  }
-  return base::TimeDelta();
+void PageLoadTracker::NotifyAbort(UserAbortType abort_type,
+                                  const base::TimeTicks& timestamp) {
+  DCHECK(abort_type != ABORT_NONE);
+  // Use UpdateAbort to update an already notified PageLoadTracker.
+  if (abort_type_ != ABORT_NONE)
+    return;
+
+  abort_type_ = abort_type;
+  abort_time_ = timestamp;
 }
 
-void PageLoadTracker::RecordTimingHistograms() {
-  DCHECK(has_commit_);
-  if (!renderer_tracked())
+void PageLoadTracker::UpdateAbort(UserAbortType abort_type,
+                                  const base::TimeTicks& timestamp) {
+  DCHECK(abort_type != ABORT_NONE);
+  DCHECK(abort_type != ABORT_OTHER);
+  DCHECK(abort_type_ == ABORT_OTHER);
+
+  abort_type_ = abort_type;
+  // For some aborts (e.g. navigations), the initiated timestamp can be earlier
+  // than the timestamp that aborted the load. Taking the minimum gives the
+  // closest user initiated time known.
+  abort_time_ = std::min(abort_time_, timestamp);
+}
+
+void PageLoadTracker::RecordTimingHistograms(const PageLoadExtraInfo& info) {
+  if (!info.first_background_time.is_zero() &&
+      !EventOccurredInForeground(timing_.first_paint, info)) {
+    if (has_commit_) {
+      PAGE_LOAD_HISTOGRAM(kHistogramBackgroundBeforePaint,
+                          info.first_background_time);
+    } else {
+      PAGE_LOAD_HISTOGRAM(kHistogramBackgroundBeforeCommit,
+                          info.first_background_time);
+    }
+  }
+
+  // The rest of the histograms require the load to have commit and be relevant.
+  if (!has_commit_ || !renderer_tracked())
     return;
 
+  // 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;
   }
 
-  base::TimeDelta background_delta = GetBackgroundDelta();
-
   if (!timing_.dom_content_loaded_event_start.is_zero()) {
-    if (timing_.dom_content_loaded_event_start < background_delta) {
+    if (EventOccurredInForeground(timing_.dom_content_loaded_event_start,
+                                  info)) {
       PAGE_LOAD_HISTOGRAM(kHistogramDomContentLoaded,
                           timing_.dom_content_loaded_event_start);
     } else {
       PAGE_LOAD_HISTOGRAM(kBackgroundHistogramDomContentLoaded,
                           timing_.dom_content_loaded_event_start);
     }
   }
   if (!timing_.load_event_start.is_zero()) {
-    if (timing_.load_event_start < background_delta) {
+    if (EventOccurredInForeground(timing_.load_event_start, info)) {
       PAGE_LOAD_HISTOGRAM(kHistogramLoad, timing_.load_event_start);
     } else {
       PAGE_LOAD_HISTOGRAM(kBackgroundHistogramLoad, timing_.load_event_start);
     }
   }
   if (timing_.first_layout.is_zero()) {
     RecordCommittedEvent(RELEVANT_LOAD_FAILED_BEFORE_FIRST_LAYOUT,
                          HasBackgrounded());
   } else {
-    if (timing_.first_layout < background_delta) {
+    if (EventOccurredInForeground(timing_.first_layout, info)) {
       PAGE_LOAD_HISTOGRAM(kHistogramFirstLayout, timing_.first_layout);
       RecordCommittedEvent(RELEVANT_LOAD_SUCCESSFUL_FIRST_LAYOUT, false);
     } else {
       PAGE_LOAD_HISTOGRAM(kBackgroundHistogramFirstLayout,
                           timing_.first_layout);
       RecordCommittedEvent(RELEVANT_LOAD_SUCCESSFUL_FIRST_LAYOUT, true);
     }
   }
   if (!timing_.first_paint.is_zero()) {
-    if (timing_.first_paint < background_delta) {
+    if (EventOccurredInForeground(timing_.first_paint, info)) {
       PAGE_LOAD_HISTOGRAM(kHistogramFirstPaint, timing_.first_paint);
     } else {
       PAGE_LOAD_HISTOGRAM(kBackgroundHistogramFirstPaint, timing_.first_paint);
     }
   }
   if (!timing_.first_text_paint.is_zero()) {
-    if (timing_.first_text_paint < background_delta) {
+    if (EventOccurredInForeground(timing_.first_text_paint, info)) {
       PAGE_LOAD_HISTOGRAM(kHistogramFirstTextPaint, timing_.first_text_paint);
     } else {
       PAGE_LOAD_HISTOGRAM(kBackgroundHistogramFirstTextPaint,
                           timing_.first_text_paint);
     }
   }
   if (!timing_.first_image_paint.is_zero()) {
-    if (timing_.first_image_paint < background_delta) {
+    if (EventOccurredInForeground(timing_.first_image_paint, info)) {
       PAGE_LOAD_HISTOGRAM(kHistogramFirstImagePaint, timing_.first_image_paint);
     } else {
       PAGE_LOAD_HISTOGRAM(kBackgroundHistogramFirstImagePaint,
                           timing_.first_image_paint);
     }
   }
   base::TimeDelta first_contentful_paint = GetFirstContentfulPaint(timing_);
   if (!first_contentful_paint.is_zero()) {
-    if (first_contentful_paint < background_delta) {
+    if (EventOccurredInForeground(first_contentful_paint, info)) {
       PAGE_LOAD_HISTOGRAM(kHistogramFirstContentfulPaint,
                           first_contentful_paint);
       // Bucket these histograms into high/low resolution clock systems. This
       // might point us to directions that will de-noise some UMA.
       if (base::TimeTicks::IsHighResolution()) {
         PAGE_LOAD_HISTOGRAM(kHistogramFirstContentfulPaintHigh,
                             first_contentful_paint);
       } else {
         PAGE_LOAD_HISTOGRAM(kHistogramFirstContentfulPaintLow,
                             first_contentful_paint);
       }
     } else {
       PAGE_LOAD_HISTOGRAM(kBackgroundHistogramFirstContentfulPaint,
                           first_contentful_paint);
     }
   }
 
   // Log time to first foreground / time to first background. Log counts that we
   // started a relevant page load in the foreground / background.
-  if (!background_time_.is_null()) {
-    PAGE_LOAD_HISTOGRAM(kHistogramFirstBackground, background_delta);
-  } else if (!foreground_time_.is_null()) {
-    PAGE_LOAD_HISTOGRAM(kHistogramFirstForeground,
-                        foreground_time_ - navigation_start_);
-  }
+  if (!info.first_background_time.is_zero())
+    PAGE_LOAD_HISTOGRAM(kHistogramFirstBackground, info.first_background_time);
+  else if (!info.first_foreground_time.is_zero())
+    PAGE_LOAD_HISTOGRAM(kHistogramFirstForeground, info.first_foreground_time);
 }
 
 void PageLoadTracker::RecordProvisionalEvent(ProvisionalLoadEvent event) {
   if (HasBackgrounded()) {
     UMA_HISTOGRAM_ENUMERATION(kBackgroundProvisionalEvents, event,
                               PROVISIONAL_LOAD_LAST_ENTRY);
   } else {
     UMA_HISTOGRAM_ENUMERATION(kProvisionalEvents, event,
                               PROVISIONAL_LOAD_LAST_ENTRY);
   }
 }
 
 // RecordCommittedEvent needs a backgrounded input because we need to special
 // case a few events that need either precise timing measurements, or different
 // logic than simply "Did I background before logging this event?"
 void PageLoadTracker::RecordCommittedEvent(CommittedRelevantLoadEvent event,
                                            bool backgrounded) {
   if (backgrounded) {
     UMA_HISTOGRAM_ENUMERATION(kBackgroundCommittedEvents, event,
                               RELEVANT_LOAD_LAST_ENTRY);
   } else {
     UMA_HISTOGRAM_ENUMERATION(kCommittedEvents, event,
                               RELEVANT_LOAD_LAST_ENTRY);
   }
 }
 
-void PageLoadTracker::RecordRappor() {
+void PageLoadTracker::RecordRappor(const PageLoadExtraInfo& info) {
+  if (!info.has_commit)
+    return;
   DCHECK(!committed_url().is_empty());
   rappor::RapporService* rappor_service =
       embedder_interface_->GetRapporService();
   if (!rappor_service)
     return;
   base::TimeDelta first_contentful_paint = GetFirstContentfulPaint(timing_);
   // Log the eTLD+1 of sites that show poor loading performance.
-  if (!first_contentful_paint.is_zero() &&
-      first_contentful_paint < GetBackgroundDelta()) {
+  if (EventOccurredInForeground(first_contentful_paint, info)) {
     scoped_ptr<rappor::Sample> sample =
         rappor_service->CreateSample(rappor::UMA_RAPPOR_TYPE);
     sample->SetStringField(
         "Domain", rappor::GetDomainAndRegistrySampleFromGURL(committed_url()));
     uint64_t bucket_index = RapporHistogramBucketIndex(first_contentful_paint);
     sample->SetFlagsField("Bucket", uint64_t(1) << bucket_index,
                           kNumRapporHistogramBuckets);
     // The IsSlow flag is just a one bit boolean if the first layout was > 10s.
     sample->SetFlagsField("IsSlow", first_contentful_paint.InSecondsF() >= 10,
                           1);
@@ skipping 17 matching lines @@
 
   MetricsWebContentsObserver* metrics = FromWebContents(web_contents);
   if (!metrics) {
     metrics =
         new MetricsWebContentsObserver(web_contents, embedder_interface.Pass());
     web_contents->SetUserData(UserDataKey(), metrics);
   }
   return metrics;
 }
 
-MetricsWebContentsObserver::~MetricsWebContentsObserver() {}
+MetricsWebContentsObserver::~MetricsWebContentsObserver() {
+  NotifyAbortAllLoads(ABORT_CLOSE);
+}
 
 bool MetricsWebContentsObserver::OnMessageReceived(
     const IPC::Message& message,
     content::RenderFrameHost* render_frame_host) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
   bool handled = true;
   IPC_BEGIN_MESSAGE_MAP_WITH_PARAM(MetricsWebContentsObserver, message,
                                    render_frame_host)
     IPC_MESSAGE_HANDLER(PageLoadMetricsMsg_TimingUpdated, OnTimingUpdated)
     IPC_MESSAGE_UNHANDLED(handled = false)
@@ skipping 30 matching lines @@
   provisional_loads_.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
-        : 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(std::move(finished_nav));
+    }
     return;
   }
   finished_nav->RecordProvisionalEvent(PROVISIONAL_LOAD_COMMITTED);
 
   // 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.
+  // 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());
+
   committed_load_ = finished_nav.Pass();
+  aborted_provisional_loads_.clear();
 
   const GURL& browser_url = web_contents()->GetLastCommittedURL();
   const std::string& mime_type = web_contents()->GetContentsMimeType();
   DCHECK(!browser_url.is_empty());
   DCHECK(!mime_type.empty());
   committed_load_->set_renderer_tracked(
       IsRelevantNavigation(navigation_handle, browser_url, mime_type));
 
   committed_load_->Commit(navigation_handle);
 }
 
+void MetricsWebContentsObserver::NavigationStopped() {
+  NotifyAbortAllLoads(ABORT_STOP);
+}
+
 void MetricsWebContentsObserver::DidRedirectNavigation(
     content::NavigationHandle* navigation_handle) {
   if (!navigation_handle->IsInMainFrame())
     return;
   auto it = provisional_loads_.find(navigation_handle);
   if (it == provisional_loads_.end())
     return;
   it->second->Redirect(navigation_handle);
 }
 
@@ skipping 13 matching lines @@
   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);

[Bryan McQuade, 2015/12/10 21:21:14]

does this happen due to a nav to a different domain in the same tab, in which
case maybe this should use ABORT_NEW_NAVIGATION?

i guess we should characterize a crash as ABORT_CLOSE (or maybe ABORT_OTHER) and
a cross-domain navigation as ABORT_NEW_NAVIGATION. not sure if we can
differentiate those here though. can you think of a way for us to distinguish
between the two cases?

[Charlie Harrison, 2015/12/10 22:00:54]

I think in practice this rarely occurs for cross-domain navigations. I actually
have an alternate proposal: just ignore this event.
1. It is rarely user initiated
2. We aren't always sure what's happening (although inspecting the termination
status gives us some indication).
3. Doing anything fancy could hamper other results. I.e. cross domain case /
browser shutdown case (our code will handle this fine)

I think clearing the loads is still smart, but we don't need to notify an abort.

[Bryan McQuade, 2015/12/10 23:02:58]

+1 agree with proposal to clear the loads but not call NotifyAbortAllLoads here.
Maybe add a short comment to explain why we don't call it here?

   committed_load_.reset();
+  provisional_loads_.clear();

[Bryan McQuade, 2015/12/10 23:02:58]

actually, if the RenderProcess for the currently committed load goes away,
should we be clearing out the provisional loads at that point? Seems like they
could potentially still continue to load in a different render process? Not
totally sure.

[Charlie Harrison, 2015/12/10 23:07:36]

Good call, you're right.

+  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);
+  }
+  // If a better signal than ABORT_OTHER came in the last 100ms, treat it as the
+  // cause of the abort (Some ABORT_OTHER signals occur before the true signal).
+  // Note that |abort_type| can only be ABORT_OTHER for provisional loads. While
+  // this  heuristic is coarse, it works better and is simpler than other
+  // feasible methods. See https://goo.gl/WKRG98.
+  for (const auto& plt : aborted_provisional_loads_) {
+    // Note that |timestamp - abort_time| can be negative.
+    if ((timestamp - plt->abort_time()).InMilliseconds() < 100)
+      plt->UpdateAbort(abort_type, timestamp);
+  }
 }
 
 void MetricsWebContentsObserver::OnTimingUpdated(
     content::RenderFrameHost* render_frame_host,
     const PageLoadTiming& timing) {
   bool error = false;
   if (!committed_load_ || !committed_load_->renderer_tracked()) {
     RecordInternalError(ERR_IPC_WITH_NO_RELEVANT_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