[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)

[Alexei Svitkine (slow), 2015/12/14 22:14:40]

Nit: No need for else if the above if already returns.

[Charlie Harrison, 2015/12/14 23:16:30]

Done.

+    return ABORT_FORWARD_BACK;
+  else if (ui::PageTransitionIsNewNavigation(transition))
+    return ABORT_NEW_NAVIGATION;
+  NOTREACHED();
+  return ABORT_OTHER;
+}
+
 // 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_NE(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_NE(abort_type, ABORT_NONE);
+  DCHECK_NE(abort_type, ABORT_OTHER);
+  DCHECK_EQ(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 10 matching lines @@
   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.
+// we have one. Don't notify aborts here because this is probably not user
+// initiated. If it is (e.g. browser shutdown), other code paths will take care
+// of notifying.
 void MetricsWebContentsObserver::RenderProcessGone(
     base::TerminationStatus status) {
+  // Other code paths will be run for normal renderer shutdown.
+  if (status == base::TERMINATION_STATUS_NORMAL_TERMINATION ||
+      status == base::TERMINATION_STATUS_STILL_RUNNING) {
+    DCHECK_NE(status, base::TERMINATION_STATUS_STILL_RUNNING);
+    return;
+  }
+
+  // If this is a crash, eagerly log the aborted provisional loads and the
+  // committed load. |provisional_loads_| don't need to be destroyed here
+  // because their lifetime is tied to the NavigationHandle.
   committed_load_.reset();
+  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& tracker : aborted_provisional_loads_) {
+    // Note that |timestamp - abort_time| can be negative.
+    if (tracker->abort_type() == ABORT_OTHER &&
+        (timestamp - tracker->abort_time()).InMilliseconds() < 100) {
+      tracker->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