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.

[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.
   // There may be slight inaccuracies due to inter-process timestamps, but
   // this solution is the best we have right now.

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

I continue to be confused by background_delta when I run into it.  It isn't
being added in this CL, but can I ask for a comment clarification anyway?  I
don't feel like the current comment is very illuminating.  Maybe "The time
between navigation and first backgrounding.  If never backgrounded, this is
TimeDelta::Max(), if started in the background, it is null.  There may be slight
innacuracies due to interprocess timestamps ..."?

Also, a suggestion: I find the value/max/null sorta confusing and inconsistent. 
Maybe just make it 0 if the page started in the background?  I think that's
valid and consistent with the other values (0 == there was no time between
navigation and first backgrounding).

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

See what you're saying. Can I update this in my RAPPOR CL where I made some
other changes already (pulled it out into its own method, and added much better
comments).

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

Sure, SG.

   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",
           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);
     }
   }
-  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,

[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);
+  }
+}
+
+// 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();
   }
 }
@@ skipping 33 matching lines @@
   // 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