Page Abort Events for relevant navigations

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/logging.h"
 #include "base/metrics/histogram.h"
 #include "components/page_load_metrics/common/page_load_metrics_messages.h"
 #include "components/page_load_metrics/common/page_load_timing.h"
@@ skipping 46 matching lines @@
 }
 
 }  // namespace
 
 #define PAGE_LOAD_HISTOGRAM(name, sample)                           \
   UMA_HISTOGRAM_CUSTOM_TIMES(name, sample,                          \
                              base::TimeDelta::FromMilliseconds(10), \
                              base::TimeDelta::FromMinutes(10), 100)
 
 PageLoadTracker::PageLoadTracker(bool in_foreground)
-    : has_commit_(false), started_in_foreground_(in_foreground) {
-  RecordEvent(PAGE_LOAD_STARTED);
-}
+    : has_commit_(false), started_in_foreground_(in_foreground) {}
 
 PageLoadTracker::~PageLoadTracker() {
-  // Even a load that failed a provisional load should log
-  // that it aborted before first layout.
-  if (timing_.first_layout.is_zero())
-    RecordEvent(PAGE_LOAD_ABORTED_BEFORE_FIRST_LAYOUT);
-
   if (has_commit_)
     RecordTimingHistograms();
 }
 
 void PageLoadTracker::WebContentsHidden() {
   // Only log the first time we background in a given page load.
-  if (background_time_.is_null()) {
+  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.
+  // Don't log foreground time if we started foregrounded.
+  if (!started_in_foreground_ && foreground_time_.is_null())
+    foreground_time_ = base::TimeTicks::Now();
 }
 
 void PageLoadTracker::Commit() {
   has_commit_ = true;
+  // This is one special case where we aren't checking if we backgrounded NOW,
+  // but at the start of the navigation.

[Bryan McQuade, 2015/10/12 16:39:22]

let's add a little more detail to explain why we choose to look at background at
nav start, rather than at any time up to the commit.

[Charlie Harrison, 2015/10/12 18:39:51]

Done.

+  RecordCommittedEvent(COMMITTED_LOAD_STARTED, !started_in_foreground_);
 }
 
-bool PageLoadTracker::UpdateTiming(const PageLoadTiming& timing) {
+bool PageLoadTracker::UpdateTiming(const PageLoadTiming& new_timing) {
   // Throw away IPCs that are not relevant to the current navigation.
-  if (!timing_.navigation_start.is_null() &&
-      timing_.navigation_start != timing.navigation_start) {
-    // TODO(csharrison) uma log a counter here
-    return false;
-  }
-  if (IsValidPageLoadTiming(timing)) {
-    timing_ = timing;
+  // Two timing structures cannot refer to the same navigation if they indicate
+  // that a navigation started at different times, so a new timing struct with a
+  // different start time from an earlier struct is considered invalid.
+  bool valid_timing_descendent =
+      timing_.navigation_start.is_null() ||
+      timing_.navigation_start == new_timing.navigation_start;
+  if (IsValidPageLoadTiming(new_timing) && valid_timing_descendent) {
+    timing_ = new_timing;
     return true;
   }

[Bryan McQuade, 2015/10/12 16:39:23]

can we add an else along with a new error enum entry to count how often this
happens?

[Charlie Harrison, 2015/10/12 18:39:51]

We do this one frame up the stack, per Randy's review. This coincides with
ERR_BAD_TIMING_IPC.

   return false;
 }
 
+bool PageLoadTracker::HasBackgrounded() {
+  return !(started_in_foreground_ && background_time_.is_null());
+}
+
 void PageLoadTracker::RecordTimingHistograms() {
   DCHECK(has_commit_);
   // 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.
   base::TimeDelta background_delta;
   if (started_in_foreground_) {
     background_delta = background_time_.is_null()
         ? base::TimeDelta::Max()
         : WallTimeFromTimeTicks(background_time_) - timing_.navigation_start;
@@ skipping 12 matching lines @@
   }
   if (!timing_.load_event_start.is_zero()) {
     if (timing_.load_event_start < background_delta) {
       PAGE_LOAD_HISTOGRAM("PageLoad.Timing2.NavigationToLoadEventFired",
                           timing_.load_event_start);
     } else {
       PAGE_LOAD_HISTOGRAM("PageLoad.Timing2.NavigationToLoadEventFired.BG",
                           timing_.load_event_start);
     }
   }
-  if (!timing_.first_layout.is_zero()) {
+  if (timing_.first_layout.is_zero()) {
+    RecordCommittedEvent(COMMITTED_LOAD_ABORTED_BEFORE_FIRST_LAYOUT,
+                         HasBackgrounded());
+  } else {
     if (timing_.first_layout < background_delta) {
       PAGE_LOAD_HISTOGRAM("PageLoad.Timing2.NavigationToFirstLayout",
                           timing_.first_layout);
-      RecordEvent(PAGE_LOAD_SUCCESSFUL_FIRST_LAYOUT_FOREGROUND);
+      RecordCommittedEvent(COMMITTED_LOAD_SUCCESSFUL_FIRST_LAYOUT, false);
     } else {
       PAGE_LOAD_HISTOGRAM("PageLoad.Timing2.NavigationToFirstLayout.BG",
                           timing_.first_layout);
-      RecordEvent(PAGE_LOAD_SUCCESSFUL_FIRST_LAYOUT_BACKGROUND);
+      RecordCommittedEvent(COMMITTED_LOAD_SUCCESSFUL_FIRST_LAYOUT, true);
     }
   }
   if (!timing_.first_text_paint.is_zero()) {
     if (timing_.first_text_paint < background_delta) {
       PAGE_LOAD_HISTOGRAM("PageLoad.Timing2.NavigationToFirstTextPaint",
                           timing_.first_text_paint);
     } else {
       PAGE_LOAD_HISTOGRAM("PageLoad.Timing2.NavigationToFirstTextPaint.BG",
                           timing_.first_text_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("PageLoad.Timing2.NavigationToFirstBackground",
+                        background_delta);
+  } else if (!foreground_time_.is_null()) {
+    PAGE_LOAD_HISTOGRAM(
+        "PageLoad.Timing2.NavigationToFirstForeground",
+        WallTimeFromTimeTicks(foreground_time_) - timing_.navigation_start);
+  }
 }
 
-void PageLoadTracker::RecordEvent(PageLoadEvent event) {
-  UMA_HISTOGRAM_ENUMERATION(
-      "PageLoad.EventCounts", event, PAGE_LOAD_LAST_ENTRY);
+void PageLoadTracker::RecordProvisionalEvent(ProvisionalLoadEvent event) {
+  if (HasBackgrounded()) {
+    UMA_HISTOGRAM_ENUMERATION("PageLoad.Events.Provisional.BG", event,
+                              PROVISIONAL_LOAD_LAST_ENTRY);
+  } else {
+    UMA_HISTOGRAM_ENUMERATION("PageLoad.Events.Provisional", 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(CommittedLoadEvent event,
+                                           bool backgrounded) {
+  if (backgrounded) {
+    UMA_HISTOGRAM_ENUMERATION("PageLoad.Events.Committed.BG", event,
+                              COMMITTED_LOAD_LAST_ENTRY);
+  } else {
+    UMA_HISTOGRAM_ENUMERATION("PageLoad.Events.Committed", event,
+                              COMMITTED_LOAD_LAST_ENTRY);
+  }
 }
 
 MetricsWebContentsObserver::MetricsWebContentsObserver(
     content::WebContents* web_contents)
     : content::WebContentsObserver(web_contents), in_foreground_(false) {}
 
 MetricsWebContentsObserver::~MetricsWebContentsObserver() {}
 
 bool MetricsWebContentsObserver::OnMessageReceived(
     const IPC::Message& message,
@@ skipping 25 matching lines @@
   if (!navigation_handle->IsInMainFrame())
     return;
 
   scoped_ptr<PageLoadTracker> finished_nav(
       provisional_loads_.take_and_erase(navigation_handle));
   DCHECK(finished_nav);
 
   // Handle a pre-commit error here. Navigations that result in an error page
   // will be ignored.
   if (!navigation_handle->HasCommitted()) {
-    finished_nav->RecordEvent(PAGE_LOAD_FAILED_BEFORE_COMMIT);
     if (navigation_handle->GetNetErrorCode() == net::ERR_ABORTED)
-      finished_nav->RecordEvent(PAGE_LOAD_ABORTED_BEFORE_COMMIT);
+      finished_nav->RecordProvisionalEvent(PROVISIONAL_LOAD_ABORTED);
+    else
+      finished_nav->RecordProvisionalEvent(PROVISIONAL_LOAD_FAILED_NON_ABORT);
     return;
   }
+  finished_nav->RecordProvisionalEvent(PROVISIONAL_LOAD_COMMITTED);
 
   // Don't treat a same-page nav as a new page load.
   if (navigation_handle->IsSamePage())
     return;
 
   // Eagerly log the previous UMA even if we don't care about the current
   // navigation.
   committed_load_.reset();
 
   if (!IsRelevantNavigation(navigation_handle))
     return;
 
   committed_load_ = finished_nav.Pass();
   committed_load_->Commit();
 }
 
 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) {
   committed_load_.reset();
 }
 
 void MetricsWebContentsObserver::OnTimingUpdated(
     content::RenderFrameHost* render_frame_host,
     const PageLoadTiming& timing) {
-  if (!committed_load_)
-    return;
+  bool error = false;
+  if (!committed_load_) {
+    UMA_HISTOGRAM_ENUMERATION("PageLoad.Events.Error",

[Bryan McQuade, 2015/10/12 16:39:22]

Is there a name we could use to convey that these errors aren't errors happening
in the page, but errors internal to the page load metrics implementation? Maybe
InternalError, InternalTrackingError, or InternalMetricsError?

+                              ERR_IPC_WITH_NO_COMMITTED_LOAD, ERR_LAST_ENTRY);
+    error = true;
+  }
 
   // We may receive notifications from frames that have been navigated away
   // from. We simply ignore them.
-  if (render_frame_host != web_contents()->GetMainFrame())
-    return;
+  if (render_frame_host != web_contents()->GetMainFrame()) {
+    UMA_HISTOGRAM_ENUMERATION("PageLoad.Events.Error", ERR_IPC_FROM_WRONG_FRAME,
+                              ERR_LAST_ENTRY);
+    error = true;
+  }
 
   // For urls like chrome://newtab, the renderer and browser disagree,
   // so we have to double check that the renderer isn't sending data from a
   // bad url like https://www.google.com/_/chrome/newtab.
-  if (!web_contents()->GetLastCommittedURL().SchemeIsHTTPOrHTTPS())
+  if (!web_contents()->GetLastCommittedURL().SchemeIsHTTPOrHTTPS()) {
+    UMA_HISTOGRAM_ENUMERATION("PageLoad.Events.Error",
+                              ERR_IPC_FROM_BAD_URL_SCHEME, ERR_LAST_ENTRY);
+    error = true;
+  }
+
+  if (error)
     return;
 
-  committed_load_->UpdateTiming(timing);
+  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.
+    UMA_HISTOGRAM_ENUMERATION("PageLoad.Events.Error", ERR_BAD_TIMING_IPC,
+                              ERR_LAST_ENTRY);
+  }
 }
 
 bool MetricsWebContentsObserver::IsRelevantNavigation(
     content::NavigationHandle* navigation_handle) {
   // 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
   // sure here that we aren't logging UMA for internal pages.
   const GURL& browser_url = web_contents()->GetLastCommittedURL();
   return navigation_handle->IsInMainFrame() &&
          !navigation_handle->IsSamePage() &&
          !navigation_handle->IsErrorPage() &&
          navigation_handle->GetURL().SchemeIsHTTPOrHTTPS() &&
          browser_url.SchemeIsHTTPOrHTTPS();
 }
 
 }  // namespace page_load_metrics