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. Tracking started_in_foreground_ for
+  // relevant loads is important data, and we can't filter by relevancy until
+  // post-commit. Background/Foreground at commit time doesn't mean much from
+  // the user's point of view.
+  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;
   }
   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_FAILED_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.Background", event,

[Bryan McQuade, 2015/10/15 03:47:36]

let's use 'BG' here rather than 'Background' for consistency with the others,
unless there's a reason we can't do that.

[Charlie Harrison, 2015/10/15 14:06:48]

Haha I agree with you, though it's going against Randy's wishes. I'll give him
time to respond before I make the change.

+                              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.Background", event,

[Bryan McQuade, 2015/10/15 03:47:36]

same - .BG for consistency

+                              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 23 matching lines @@
 void MetricsWebContentsObserver::DidFinishNavigation(
     content::NavigationHandle* navigation_handle) {
   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.
+  // will be ignored. Note that downloads/204s will result in HasCommitted()
+  // returning false.
   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 if (navigation_handle->GetNetErrorCode() != net::OK)
+      finished_nav->RecordProvisionalEvent(PROVISIONAL_LOAD_FAILED_NON_ABORT);
     return;

[Bryan McQuade, 2015/10/15 03:47:36]

is it ever valid for HasCommitted() to be false and GetNetErrorCode() to be
net::OK? if so, do we need a new provisional load event to handle that case? if
not, let's log an InternalError in an else clause just to make sure we aren't
hitting that case.

[Charlie Harrison, 2015/10/15 14:06:48]

After looking through the navigation code, I'm not sure if this is possible, or
if it is an error if it is :P. I'll keep investigating.

[Bryan McQuade, 2015/10/15 14:12:41]

Sounds good. I'd propose adding an error enum (any maybe a DCHECK) even if it's
currently not possible, just in case code changes in the future such that it
becomes possible.

[Charlie Harrison, 2015/10/15 15:13:49]

According to clamy, this will signal a user stopping a navigation
post-PlzNavigate. It should not fire pre-PlzNavigate.

[Bryan McQuade, 2015/10/15 15:17:55]

great, thanks for investigating that. what do you think we should do in the
meantime? maybe add a DCHECK and a comment noting that we do expect this to
start firing eventually as part of plznavigate, and want to update our code to
handle that case once it happens. maybe also file a bug against plznavigate
folks about this so they remember to help us update this bit of code once the
plznav changes are ready.

   }
+  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.InternalError",
+                              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.InternalError",
+                              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.InternalError",
+                              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.InternalError",
+                              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