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) {
+  if (in_foreground)
+    background_time_ = base::Time::Max();
+}
+
+PageLoadTracker::~PageLoadTracker() {
+  if (has_commit_)
+    RecordTimingHistograms();
+}
+
+void PageLoadTracker::WebContentsHidden() {
+  // Only log the first time we background in a given page load.
+  if (!background_time_.is_max())
+    return;
+
+  // 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.
+  background_time_ = base::Time::FromDoubleT(
+      (base::TimeTicks::Now() - base::TimeTicks::UnixEpoch()).InSecondsF());
+}
+
+void PageLoadTracker::Commit() {
+  has_commit_ = 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 we start in the foreground, |background_delta| will be extremely large
+  // (Max() - nav_start), and if we start in the background, |background_delta|
+  // will be extremely small (0 - nav_start).
+  base::TimeDelta background_delta =

[Bryan McQuade, 2015/09/29 00:32:19]

Let's be a little more explicit about the handling of the special max value.
Something like:

background_delta = background_time_.is_max() ? TimeDelta::Max() :
background_time_ - timing.navigation_start;

[Bryan McQuade, 2015/09/29 12:38:52]

Actually, there are two cases we should handle explicitly, just so other readers
of the code remember them as well:
* background_time_ is max (webcontents was never backgrounded): delta should be
max
* background_time_ is zero (webcontents was backgrounded when constructed):
delta should be zero

The logic around this is just complex enough that it might be good to factor
into a helper method in an anonymous namespace, but it's up to you.

[Charlie Harrison, 2015/09/29 14:13:07]

Good idea. Done.

+      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.Timing.NavigationToDOMContentLoadedEventFired",
+          timing_.dom_content_loaded_event_start);
+    } else {
+      PAGE_LOAD_HISTOGRAM(
+          "PageLoad.Timing.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.Timing.NavigationToLoadEventFired",
+                          timing_.load_event_start);
+    } else {
+      PAGE_LOAD_HISTOGRAM("PageLoad.Timing.NavigationToLoadEventFired.BG",
+                          timing_.load_event_start);
+    }
+  }
+  if (!timing_.first_layout.is_zero()) {
+    if (timing_.first_layout < background_delta) {
+      PAGE_LOAD_HISTOGRAM("PageLoad.Timing.NavigationToFirstLayout",
+                          timing_.first_layout);
+    } else {
+      PAGE_LOAD_HISTOGRAM("PageLoad.Timing.NavigationToFirstLayout.BG",
+                          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::DidFinishNavigation(
     content::NavigationHandle* navigation_handle) {
+  if (!navigation_handle->IsInMainFrame())
+    return;
+
+  scoped_ptr<PageLoadTracker> finished_nav(
+      provisional_loads_.take_and_erase(navigation_handle));
+

[Bryan McQuade, 2015/09/29 00:32:19]

let's move the DCHECK from below up here:
DCHECK(finished_nav);

[Charlie Harrison, 2015/09/29 14:13:07]

Done.

+  // TODO(csharrison) handle the two error cases:
+  // 1. Error pages that replace the previous page.
+  // 2. Error pages that leave the user on the previous page.
+  // For now these cases will be ignored.
   if (!navigation_handle->HasCommitted())

[Bryan McQuade, 2015/09/29 00:32:19]

what's the difference between testing !HasCommitted and IsErrorPage? should we
test both or perhaps add a DCHECK(IsErrorPage()) when HasCommitted is false
here, just to sanity check our assumptions?

[Charlie Harrison, 2015/09/29 14:13:07]

IsErrorPage is true when HasCommitted is true and the navigation resulted in an
error page. If we toss !HasCommitted and !IsErrorPage (in IsRelevantNavigation)
then we don't log UMA for error'ed navigations.

     return;
-  if (navigation_handle->IsInMainFrame() && !navigation_handle->IsSamePage())
-    RecordTimingHistograms();
-  if (IsRelevantNavigation(navigation_handle))
-    current_timing_.reset(new PageLoadTiming());
+
+  if (!IsRelevantNavigation(navigation_handle))

[Bryan McQuade, 2015/09/29 00:32:19]

thinking about this more, I do think we should log and discard the current
committed PageLoadTracker a bit more eagerly when we get a new non-in-page
commit. I feel uneasy potentially holding on to data that should be logged until
later, since we're then logging that data potentially long after the nav
completes.

As you point out, we should not discard and log on an in-page navigation, but I
feel that we should discard and log for all main frame non-in-page navs.

similar to how you do:
if (!navigation_handle->HasCommitted())
  return;

can we add:
// Do not treat in-page navigations as new page loads.
if (navigation_handle->IsSamePage())
  return;

// Trigger recording of timing histograms for the previous PageLoadTracker, if
any.
committed_load_.reset();

if (!IsRelevantNavigation(navigation_handle))
  return;

committed_load_ = finished_nav.Pass();
committed_load_->Commit();

This makes sure we log more eagerly, and I like being explicit about the
force-log step by calling reset(), rather than implicitly during the assignment
from finished_nav.Pass();

[Charlie Harrison, 2015/09/29 14:13:07]

I have no objections to that! Done.

+    return;
+
+  // Updating |committed_load_| will trigger RecordTimingHistograms on a
+  // previous PageLoadTracker.
+  committed_load_ = finished_nav.Pass();
+  DCHECK(committed_load_);
+  committed_load_->Commit();
 }
 
-// This will occur when the process for the main RenderFrameHost exits.
-// This will happen with a normal exit or a crash.
-void MetricsWebContentsObserver::RenderProcessGone(

[Bryan McQuade, 2015/09/29 00:32:19]

if removing this causes us to log metrics less eagerly, i think it's worth
keeping it and explicitly invoking committed_load_.reset() here instead, with a
short comment to explain.

[Charlie Harrison, 2015/09/29 14:13:07]

Yeah I think it could. Done.

-    base::TerminationStatus status) {
-  RecordTimingHistograms();
+void MetricsWebContentsObserver::DidStartNavigation(

[Bryan McQuade, 2015/09/29 00:32:19]

let's put DidStartNavigation impl before DidFinishNavigation.

[Charlie Harrison, 2015/09/29 14:13:07]

Done.

+    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::WasShown() {
+  in_foreground_ = true;
+}
+
+void MetricsWebContentsObserver::WasHidden() {
+  in_foreground_ = false;
+  if (committed_load_)
+    committed_load_->WebContentsHidden();
+  for (const auto& kv : provisional_loads_) {
+    kv.second->WebContentsHidden();
+  }
+}
 
 void MetricsWebContentsObserver::OnTimingUpdated(
     content::RenderFrameHost* render_frame_host,
     const PageLoadTiming& timing) {

[Bryan McQuade, 2015/09/29 00:32:19]

we used to have:
if (!current_timing)
  return;

which protected against getting an OnTimingUpdated when we weren't tracking
metrics.

Should we have something similar to make sure we don't end up calling
committed_load_->UpdateTiming(...); on a null pointer, below? e.g.:
if (!committed_load_)
  return;

[Charlie Harrison, 2015/09/29 14:13:07]

I removed it under the assumption that DidStartNavigation would be called before
any IPCs get sent. I think it'd be a good idea to keep it just in case though.

-  if (!current_timing_)
-    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->IsErrorPage() &&
          navigation_handle->GetURL().SchemeIsHTTPOrHTTPS() &&
          browser_url.SchemeIsHTTPOrHTTPS();
 }
 
 }  // namespace page_load_metrics