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;
+  // We log the event that this load started. Because we don't know if a load is
+  // relevant or if it will commit before now, we have to log this event at
+  // commit time.
+  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());

[Alexei Svitkine (slow), 2015/10/16 15:43:14]

Nit: !(a && b) -> !a || !b

[Charlie Harrison, 2015/10/16 16:05:06]

Done.

+}
+
 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;
   }
 
   if (!timing_.dom_content_loaded_event_start.is_zero()) {
     if (timing_.dom_content_loaded_event_start < background_delta) {
       PAGE_LOAD_HISTOGRAM(
           "PageLoad.Timing2.NavigationToDOMContentLoadedEventFired",
           timing_.dom_content_loaded_event_start);
     } else {
       PAGE_LOAD_HISTOGRAM(
-          "PageLoad.Timing2.NavigationToDOMContentLoadedEventFired.BG",
+          "PageLoad.Timing2.NavigationToDOMContentLoadedEventFired.Background",
           timing_.dom_content_loaded_event_start);
     }
   }
   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);
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Timing2.NavigationToLoadEventFired.Background",
+          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",
+      PAGE_LOAD_HISTOGRAM("PageLoad.Timing2.NavigationToFirstLayout.Background",
                           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);
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Timing2.NavigationToFirstTextPaint.Background",
+          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,
+                              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,
+                              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);
+    net::Error error = navigation_handle->GetNetErrorCode();
+    finished_nav->RecordProvisionalEvent(
+        error == net::OK ? PROVISIONAL_LOAD_STOPPED
+        : error == net::ERR_ABORTED ? PROVISIONAL_LOAD_ERR_ABORTED
+        : PROVISIONAL_LOAD_ERR_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.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);

[Alexei Svitkine (slow), 2015/10/16 15:43:15]

Please make a helper function for this histogram, with the enum as the param.
Each macro expands to a bunch of machine code, so this way you reduce the bloat.

[Charlie Harrison, 2015/10/16 16:05:06]

Done. Good call.

+    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();
+  std::string mime = web_contents()->GetContentsMimeType();

[Bryan McQuade, 2015/10/16 15:01:29]

GetContentsMimeType only returns the correct value after a certain point in the
navigation. If we happened to try to call IsRelevantNavigation from somewhere
else in the code, we might get an empty string here, or possibly the mime type
of the prior nav, and it would not be immediately obvious at the call site that
that could happen (though tests should fail, but i'd like it to be more apparent
to the caller). So I think it's important that callers of this method are aware
of the input params and take care to think about whether they can get valid
values for those params at the time they call.

I'd propose making IsRelevantNavigation a non-class method in the anonymous
namespace above that takes all params required for it to make policy decisions:

bool IsRelevantNavigation(content::NavigationHandle* navigation_handle, 
    const std::string& browser_url,
    const std::string& mime_type);

That way the caller is responsible for providing valid values, forcing them to
make sure they can get the right url and mime type at the point of invocation.

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

nit: since GetContentsMimeType returns a const std::string&, let's change the
type here to const std::string& as well to avoid the string copy

[Charlie Harrison, 2015/10/16 16:05:06]

Done.

   return navigation_handle->IsInMainFrame() &&
          !navigation_handle->IsSamePage() &&
          !navigation_handle->IsErrorPage() &&
          navigation_handle->GetURL().SchemeIsHTTPOrHTTPS() &&
-         browser_url.SchemeIsHTTPOrHTTPS();
+         browser_url.SchemeIsHTTPOrHTTPS() &&
+         (mime == "text/html" || mime == "application/xhtml+xml");
 }
 
 }  // namespace page_load_metrics