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 51 matching lines @@
   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);
 }
 
 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()) {
     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.

[Randy Smith (Not in Mondays), 2015/10/06 19:24:00]

I'm confused by this sentence.  If we started foregrounded and never go
background, foreground_time_ will be null and (presumably, haven't read the
paired code yet) won't be logged.  But if we started foreground, go background,
and then go foreground again, foregrount_time_ will not be null.  So shouldn't
we be testing started_in_foreground_?

(This may just be me bering confused by a comment that's not in the right place,
i.e. not near the code it refers to?)

[Charlie Harrison, 2015/10/06 19:35:36]

You're right this code could be more clear. Later we test
!foreground_time_.is_null() && !started_in_foreground_, but I'll move some of
that logic here.

+  if (foreground_time_.is_null()) {
+    foreground_time_ = base::TimeTicks::Now();
+  }
+}
+
 void PageLoadTracker::Commit() {
   has_commit_ = true;
+  // We only know page relevancy post-commit.
+  if (started_in_foreground_)
+    RecordEvent(PAGE_LOAD_RELEVANT_STARTED_IN_FOREGROUND);
+  else
+    RecordEvent(PAGE_LOAD_RELEVANT_STARTED_IN_BACKGROUND);
 }
 
 bool PageLoadTracker::UpdateTiming(const PageLoadTiming& 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)) {
+  bool valid_timing_descendent = timing_.navigation_start.is_null() ||

[Randy Smith (Not in Mondays), 2015/10/06 19:24:00]

nit, suggestion: I dislike creating temporary variables for single use.  To the
extent that documentation is needed, I'd rather have a comment.  But up to you.

Part of this is because I don't understand what "valid_timing_descendent" means;
whether you accept the above suggestion or not, could you add a comment
explaining that?

+      timing_.navigation_start == timing.navigation_start;
+  if (IsValidPageLoadTiming(timing) && valid_timing_descendent) {
     timing_ = timing;
     return true;
   }
+  RecordEvent(PAGE_LOAD_BAD_IPC);
   return false;
 }
 
 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_) {
@@ skipping 15 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()) {
+    RecordEvent(PAGE_LOAD_ABORTED_BEFORE_FIRST_LAYOUT);
+    RecordEvent(PAGE_LOAD_RELEVANT_ABORTED_BEFORE_FIRST_LAYOUT);
+  } else {
     if (timing_.first_layout < background_delta) {
       PAGE_LOAD_HISTOGRAM("PageLoad.Timing2.NavigationToFirstLayout",
                           timing_.first_layout);
       RecordEvent(PAGE_LOAD_SUCCESSFUL_FIRST_LAYOUT_FOREGROUND);
     } else {
       PAGE_LOAD_HISTOGRAM("PageLoad.Timing2.NavigationToFirstLayout.BG",
                           timing_.first_layout);
       RecordEvent(PAGE_LOAD_SUCCESSFUL_FIRST_LAYOUT_BACKGROUND);
     }
   }
-
+  // Log time to first foreground / time to first background. Log counts that we
+  // started a relevant page load in the foreground / background.
+  if (started_in_foreground_ && !background_time_.is_null()) {
+    PAGE_LOAD_HISTOGRAM(
+        "PageLoad.Timing2.NavigationToFirstBackground", background_delta);
+  } else if (!started_in_foreground_ && !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);
 }
 
 MetricsWebContentsObserver::MetricsWebContentsObserver(
     content::WebContents* web_contents)
     : content::WebContentsObserver(web_contents), in_foreground_(false) {}
@@ skipping 31 matching lines @@
     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)
+    if (navigation_handle->GetNetErrorCode() == net::ERR_ABORTED) {
       finished_nav->RecordEvent(PAGE_LOAD_ABORTED_BEFORE_COMMIT);
+      finished_nav->RecordEvent(PAGE_LOAD_ABORTED_BEFORE_FIRST_LAYOUT);
+    }
     return;
   }
 
   // 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