Page Abort Events for relevant navigations

components/page_load_metrics/browser/metrics_web_contents_observer.cc

Index: components/page_load_metrics/browser/metrics_web_contents_observer.cc
diff --git a/components/page_load_metrics/browser/metrics_web_contents_observer.cc b/components/page_load_metrics/browser/metrics_web_contents_observer.cc
index 2961f1ecb5dd766e48da0cd1dc87bd6f8ba53cb7..9b8c4d63b5729720b23ff2703f4905370af47ae0 100644
--- a/components/page_load_metrics/browser/metrics_web_contents_observer.cc
+++ b/components/page_load_metrics/browser/metrics_web_contents_observer.cc
@@ -64,45 +64,52 @@ base::Time WallTimeFromTimeTicks(base::TimeTicks time) {
                              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.

[Randy Smith (Not in Mondays), 2015/10/08 19:07:11]

Scanning the rest of the file for the usage of the second argument of
RecordCommittedEvent, this comment seems off to me--the rest of the file look
like it's checking not if the page is in the background at the time of the
event, but if it's been backgrounded at any point since it started.

I'm also confused by why we want to do things differently for this statistic. 
My primary concern is that it makes this number incomparable with the other
numbers in the histogram.  But I'm also not certain why we want to know whether
or not the page was started in the foreground; what are we going to do with that
information?

[Charlie Harrison, 2015/10/08 21:27:02]

I think it adds a little more context to the backgrounded navigations. A
navigation started in the background signals a different user intent than one
started in the foreground, then backgrounded. IMO not special casing this makes
the metrics not that useful, because commit-time does not signal anything
special to the user.

+  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;
+  // A valid timing struct is one that has the same navigation start as the
+  // previous one (if the previous one had a navigation start at all).

[Randy Smith (Not in Mondays), 2015/10/08 19:07:11]

This mostly just duplicates what the code says.  That can be useful, but more
useful is saying *why* a timing struct is valid iff it has the same navigation
start as a previous one is more useful.   Maybe "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 an different start time from an
earlier struct is considered invalid."?

[Charlie Harrison, 2015/10/08 21:27:02]

Done.

+  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;
   }
+  RecordCommittedEvent(COMMITTED_LOAD_BAD_IPC, HasBackgrounded());

[Randy Smith (Not in Mondays), 2015/10/08 19:07:10]

I'm a bit uncomfortable within recording this event in a routine that doesn't,
on the surface, have anything to do with IPC.  Maybe pull this into the caller
and conditionalize it on the routine return value?  (Though I see the caller
isn't obviously IPC related either, but it's closer.)

[Charlie Harrison, 2015/10/08 21:27:02]

Done.

   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.
@@ -135,15 +142,18 @@ void PageLoadTracker::RecordTimingHistograms() {
                           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()) {
@@ -155,11 +165,40 @@ void PageLoadTracker::RecordTimingHistograms() {
                           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::RecordProvisionalEvent(ProvisionalLoadEvent event) {
+  if (HasBackgrounded()) {
+    UMA_HISTOGRAM_ENUMERATION("PageLoad.Events.Provisional.BG", event,

[Randy Smith (Not in Mondays), 2015/10/08 19:07:10]

I'd like to get rid of "BG" and use "Background" and "Foreground".  The custom
in Chromium is to avoid abbreviations
(http://google-styleguide.googlecode.com/svn/trunk/cppguide.html#General_Namin...).

[Charlie Harrison, 2015/10/08 21:27:02]

Is it worth it to have to deprecate the PageLoad.Timing2.* metrics for this
change?

[Randy Smith (Not in Mondays), 2015/10/12 15:45:22]

I think I'd say "No, but I still think we should do it right for
PageLoad.Events.Provisional.*".

+                              PROVISIONAL_LOAD_LAST_ENTRY);
+  } else {
+    UMA_HISTOGRAM_ENUMERATION("PageLoad.Events.Provisional", event,
+                              PROVISIONAL_LOAD_LAST_ENTRY);
+  }
 }
 
-void PageLoadTracker::RecordEvent(PageLoadEvent event) {
-  UMA_HISTOGRAM_ENUMERATION(
-      "PageLoad.EventCounts", event, PAGE_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(
@@ -205,11 +244,13 @@ void MetricsWebContentsObserver::DidFinishNavigation(
   // 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())
@@ -228,6 +269,11 @@ void MetricsWebContentsObserver::DidFinishNavigation(
 
 void MetricsWebContentsObserver::WasShown() {
   in_foreground_ = true;
+  if (committed_load_)
+    committed_load_->WebContentsShown();
+  for (const auto& kv : provisional_loads_) {
+    kv.second->WebContentsShown();
+  }
 }
 
 void MetricsWebContentsObserver::WasHidden() {