Separate page load metrics for backgrounded pages

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 31 matching lines @@
       !timing.load_event_start.is_zero(),
       !timing.dom_content_loaded_event_start.is_zero() &&
       timing.response_start <= timing.load_event_start &&
       timing.dom_content_loaded_event_start <= timing.load_event_start);
 
   return true;
 }
 
 }  // 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),
+      has_finished_(false),
+      page_load_stayed_in_foreground_(in_foreground) {}
+
+PageLoadTracker::~PageLoadTracker() {
+  if (has_commit_)
+    RecordTimingHistograms();
+}
+
+void PageLoadTracker::WebContentsHidden() {
+  if (!has_finished_)

[Bryan McQuade, 2015/09/24 18:21:52]

let's chat about this and some possible alternatives a bit next week. onload is
probably a decent signal for many pages, but there are others where the entire
page load, from a user standpoint, happens entirely after onload. if we can come
up with a mechanism that doesn't care about onload i think i'd prefer that. one
alternative would be to log metrics observed up until the time the web contents
got hidden, and then stop recording metrics for that page. that way, we log
metrics for what the user experienced only. let's chat more next week.

[Charlie Harrison, 2015/09/24 18:49:07]

Sounds good. I'm hesitant about logging partial structs before background unless
we name them something else. Otherwise they will be conflated with
failed/aborted loads.

+    page_load_stayed_in_foreground_ = false;
+}
+
+void PageLoadTracker::Commit() {
+  has_commit_ = true;
+}
+
+void PageLoadTracker::Finish() {
+  has_finished_ = true;
+}
+
+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)) {
+    timing_ = timing;
+    return true;
+  }
+  return false;
+}
+
+void PageLoadTracker::RecordTimingHistograms() {
+  DCHECK(has_commit_);
+  if (!timing_.dom_content_loaded_event_start.is_zero()) {
+    if (page_load_stayed_in_foreground_) {
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Timing.NavigationToDOMContentLoadedEventFired",
+          timing_.dom_content_loaded_event_start);
+    } else {
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Timing.BG.NavigationToDOMContentLoadedEventFired",
+          timing_.dom_content_loaded_event_start);
+    }
+  }
+  if (!timing_.load_event_start.is_zero()) {
+    if (page_load_stayed_in_foreground_) {
+      PAGE_LOAD_HISTOGRAM("PageLoad.Timing.NavigationToLoadEventFired",
+                          timing_.load_event_start);
+    } else {
+      PAGE_LOAD_HISTOGRAM("PageLoad.Timing.BG.NavigationToLoadEventFired",
+                          timing_.load_event_start);
+    }
+  }
+  if (!timing_.first_layout.is_zero()) {
+    if (page_load_stayed_in_foreground_) {
+      PAGE_LOAD_HISTOGRAM("PageLoad.Timing.NavigationToFirstLayout",
+                          timing_.first_layout);
+    } else {
+      PAGE_LOAD_HISTOGRAM("PageLoad.Timing.BG.NavigationToFirstLayout",
+                          timing_.first_layout);
+    }
+  }
+}
+
 MetricsWebContentsObserver::MetricsWebContentsObserver(
     content::WebContents* web_contents)
-    : content::WebContentsObserver(web_contents) {}
+    : content::WebContentsObserver(web_contents), in_foreground_(false) {}
 
-// This object is tied to a single WebContents for its entire lifetime.
-MetricsWebContentsObserver::~MetricsWebContentsObserver() {
-  RecordTimingHistograms();
-}
+MetricsWebContentsObserver::~MetricsWebContentsObserver() {}
 
 bool MetricsWebContentsObserver::OnMessageReceived(
     const IPC::Message& message,
     content::RenderFrameHost* render_frame_host) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
   bool handled = true;
   IPC_BEGIN_MESSAGE_MAP_WITH_PARAM(MetricsWebContentsObserver, message,
                                    render_frame_host)
     IPC_MESSAGE_HANDLER(PageLoadMetricsMsg_TimingUpdated, OnTimingUpdated)
     IPC_MESSAGE_UNHANDLED(handled = false)
   IPC_END_MESSAGE_MAP()
   return handled;
 }
 
 void MetricsWebContentsObserver::DidCommitNavigation(
     content::NavigationHandle* navigation_handle) {
-  if (navigation_handle->IsInMainFrame() && !navigation_handle->IsSamePage())
-    RecordTimingHistograms();
-  if (IsRelevantNavigation(navigation_handle))
-    current_timing_.reset(new PageLoadTiming());
+  if (!navigation_handle->IsInMainFrame())
+    return;
+
+  // If the provisional load is a relevant navigation (which we only know for
+  // sure after commit), then we update |committed_load_|. We always remove a
+  // provisional navigation from |provisional_loads_| on commit.
+  if (IsRelevantNavigation(navigation_handle)) {
+    // Updating |committed_load_| will trigger RecordTimingHistograms on a
+    // previous PageLoadTracker.
+    committed_load_ = provisional_loads_.take_and_erase(navigation_handle);
+    DCHECK(committed_load_);
+    committed_load_->Commit();
+  } else {
+    provisional_loads_.erase(navigation_handle);

[Bryan McQuade, 2015/09/24 18:21:52]

should we also call
committed_load_.reset();
here to force logging of the previous tracker if any?

Perhaps instead we should just do that unconditionally above the call to
IsRelevantNavigation(...) along with a comment just to be super explicit that we
want to destruct the previous one if any in order to trigger recording of
histograms.

[Charlie Harrison, 2015/09/24 18:49:07]

I'm not sure. Can't a same-page navigation commit before a page has fully
loaded? Best to wait as long as possible to log so we don't log early.

+  }
 }
 
-// This will occur when the process for the main RenderFrameHost exits.
-// This will happen with a normal exit or a crash.
-void MetricsWebContentsObserver::RenderProcessGone(
-    base::TerminationStatus status) {
-  RecordTimingHistograms();
+void MetricsWebContentsObserver::DidStartNavigation(
+    content::NavigationHandle* navigation_handle) {
+  if (!navigation_handle->IsInMainFrame())
+    return;
+  // We can have two provisional loads in some cases. E.g. a same-site
+  // navigation can have a concurrent cross-process navigation started
+  // from the omnibox.
+  DCHECK(provisional_loads_.size() < 2);
+  provisional_loads_.insert(
+      navigation_handle, make_scoped_ptr(new PageLoadTracker(in_foreground_)));
 }
 
-#define PAGE_LOAD_HISTOGRAM(name, sample)                           \
-  UMA_HISTOGRAM_CUSTOM_TIMES(name, sample,                          \
-                             base::TimeDelta::FromMilliseconds(10), \
-                             base::TimeDelta::FromMinutes(10), 100);
+void MetricsWebContentsObserver::DidFinishLoad(
+    content::RenderFrameHost* render_frame_host,
+    const GURL& validated_url) {
+  if (render_frame_host == web_contents()->GetMainFrame() && committed_load_)
+    committed_load_->Finish();
+}
+
+void MetricsWebContentsObserver::DidFailLoad(
+    content::RenderFrameHost* render_frame_host,
+    const GURL& validated_url,
+    int error_code,
+    const base::string16& error_description,
+    bool was_ignored_by_handler) {
+  if (render_frame_host == web_contents()->GetMainFrame() && committed_load_)
+    committed_load_->Finish();
+}
+
+void MetricsWebContentsObserver::WasShown() {
+  in_foreground_ = true;
+}
+void MetricsWebContentsObserver::WasHidden() {
+  in_foreground_ = false;
+  if (committed_load_)
+    committed_load_->WebContentsHidden();
+  for (auto kv : provisional_loads_) {

[Bryan McQuade, 2015/09/24 18:21:52]

auto is awesome but subtle. if you just say 'auto' it's equivalent to just
typing the type of the object (non-const, non-reference) which can cause a copy
constructor to be invoked in some cases as you iterate each element. just to be
sure to avoid that, i like to do:
const auto& kv : provisional_loads_
or if operating on non-const data:
auto& kv : provisional_loads_
which avoids a copy in many cases

[Charlie Harrison, 2015/09/24 18:49:07]

Yeah good idea.

+    kv.second->WebContentsHidden();
+  }
+}
 
 void MetricsWebContentsObserver::OnTimingUpdated(
     content::RenderFrameHost* render_frame_host,
     const PageLoadTiming& timing) {
-  if (!current_timing_)

[Bryan McQuade, 2015/09/24 18:21:52]

should we still continue to return if committed_load_ is null?

-    return;
-
   // We may receive notifications from frames that have been navigated away
   // from. We simply ignore them.
   if (render_frame_host != web_contents()->GetMainFrame())
     return;
 
   // 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())
     return;
 
-  // Throw away IPCs that are not relevant to the current navigation.
-  if (!current_timing_->navigation_start.is_null() &&
-      timing.navigation_start != current_timing_->navigation_start) {
-    // TODO(csharrison) uma log a counter here
-    return;
-  }
-
-  *current_timing_ = timing;
-}
-
-void MetricsWebContentsObserver::RecordTimingHistograms() {
-  if (!current_timing_ || !IsValidPageLoadTiming(*current_timing_))
-    return;
-
-  if (!current_timing_->dom_content_loaded_event_start.is_zero()) {
-    PAGE_LOAD_HISTOGRAM(
-        "PageLoad.Timing.NavigationToDOMContentLoadedEventFired",
-        current_timing_->dom_content_loaded_event_start);
-  }
-
-  if (!current_timing_->load_event_start.is_zero()) {
-    PAGE_LOAD_HISTOGRAM("PageLoad.Timing.NavigationToLoadEventFired",
-                        current_timing_->load_event_start);
-  }
-
-  if (!current_timing_->first_layout.is_zero()) {
-    PAGE_LOAD_HISTOGRAM("PageLoad.Timing.NavigationToFirstLayout",
-                        current_timing_->first_layout);
-  }
-  current_timing_.reset();
+  committed_load_->UpdateTiming(timing);
 }
 
 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->HasCommittedDocument() &&
          navigation_handle->GetURL().SchemeIsHTTPOrHTTPS() &&
          browser_url.SchemeIsHTTPOrHTTPS();
 }
 
 }  // namespace page_load_metrics