PageLoadMetrics renderer and browser implementation.

components/page_load_metrics/browser/page_load_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/page_load_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"
+#include "content/public/browser/browser_thread.h"
+#include "content/public/browser/navigation_details.h"
+#include "content/public/browser/navigation_handle.h"
+#include "content/public/browser/render_frame_host.h"
+#include "content/public/browser/web_contents.h"
+#include "content/public/browser/web_contents_observer.h"
+#include "content/public/browser/web_contents_user_data.h"
+#include "ipc/ipc_message.h"
+#include "ipc/ipc_message_macros.h"
+
+DEFINE_WEB_CONTENTS_USER_DATA_KEY(page_load_metrics::WebContentsObserver);
+
+namespace page_load_metrics {
+
+namespace {
+
+// True if the timing structs have the same navigation start.
+bool PageLoadTimingIsChild(const PageLoadTiming& timing,
+                           const PageLoadTiming& parent) {
+  return (parent.navigation_start.is_null() ||
+          timing.navigation_start == parent.navigation_start);
+}
+
+bool PageLoadTimingIsComplete(const PageLoadTiming& timing) {
+  return !timing.navigation_start.is_null() &&
+      !timing.response_start.is_zero() &&
+      !timing.dom_content_loaded_event_start.is_zero() &&
+         !timing.load_event_start.is_zero() &&
+         !timing.first_layout.is_zero();
+}
+
+// Checks guaranteed ordering for performance events.
+// Assumes IsComplete().
+// Order: navigation_start => response_start =>
+// dom_content_loaded_event_start => load_event_start
+bool PageLoadTimingIsOrdered(const PageLoadTiming& timing) {
+  return !timing.response_start.is_zero() &&
+         timing.response_start < timing.dom_content_loaded_event_start &&
+         timing.dom_content_loaded_event_start < timing.load_event_start;
+}
+
+}  // namespace
+WebContentsObserver::WebContentsObserver(content::WebContents* web_contents)
+    : content::WebContentsObserver(web_contents) {}
+
+WebContentsObserver::~WebContentsObserver() {
+  RecordTimingHistograms();

[Bryan McQuade, 2015/09/04 20:53:17]

let's add a short comment here to note the cases where this happens (is it just
browser shutdown?)

[Charlie Harrison, 2015/09/08 23:05:15]

Done.

+}
+
+bool WebContentsObserver::OnMessageReceived(
+    const IPC::Message& message,
+    content::RenderFrameHost* render_frame_host) {
+  DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
+  return HandleMessageReceived(message, render_frame_host);
+}
+
+void WebContentsObserver::DidCommitNavigation(
+    content::NavigationHandle* navigation_handle) {
+  RecordTimingHistograms();

[Bryan McQuade, 2015/09/04 20:53:17]

we only want to RecordTimingHistograms() if this is a main-frame navigation
that's not in-page. you probably need logic at the beginning of this function
like:

if (!navigation_handle->IsInMainFrame() || navigation_handle->IsSamePage())
  return;

RecordTimingHistograms();

if (IsRelevantNavigation(...))
  current_timing_.reset(new PageLoadTiming());

[Charlie Harrison, 2015/09/08 23:05:15]

Done.

+  if (IsRelevantNavigation(navigation_handle)) {
+    current_timing_.reset(new PageLoadTiming());
+    current_navigation_ = navigation_handle;

[Bryan McQuade, 2015/09/04 20:53:17]

looks like we're no longer using current_navigation_ - maybe we can remove it?

[Charlie Harrison, 2015/09/08 23:05:15]

Done.

+  }
+}
+
+void WebContentsObserver::RenderProcessGone(base::TerminationStatus status) {
+  RecordTimingHistograms();

[Bryan McQuade, 2015/09/04 20:53:17]

let's add a short comment here to note where this happens (render process crash,
and tab close?)

[Charlie Harrison, 2015/09/08 23:05:15]

Done.

+}
+
+bool WebContentsObserver::HandleMessageReceived(

[Bryan McQuade, 2015/09/04 20:53:17]

minor suggestion: even though it makes the method ordering different from what's
in the header, i think it'd be better to put the impementation of this method
immediately after OnMessageReceived. That allows readers to just continue
reading w/o having to jump around in the file.

[Charlie Harrison, 2015/09/08 23:05:15]

Done.

+    const IPC::Message& message,
+    content::RenderFrameHost* render_frame_host) {
+  bool handled = true;
+  IPC_BEGIN_MESSAGE_MAP_WITH_PARAM(WebContentsObserver, message,
+                                   render_frame_host)
+    IPC_MESSAGE_HANDLER(PageLoadMetricsMsg_TimingUpdated,
+                        OnTimingUpdated)
+    IPC_MESSAGE_UNHANDLED(handled = false)
+  IPC_END_MESSAGE_MAP()
+  return handled;
+}
+
+#define PAGE_LOAD_HISTOGRAM(name, sample)                           \
+  UMA_HISTOGRAM_CUSTOM_TIMES(name, sample,                          \
+                             base::TimeDelta::FromMilliseconds(10), \
+                             base::TimeDelta::FromMinutes(10), 100);
+
+void WebContentsObserver::OnTimingUpdated(
+    content::RenderFrameHost* render_frame_host,
+    const PageLoadTiming& timing) {
+  if (!current_timing_)
+    return;
+
+  // See above comment about browser/renderer url disagreement (newtab).

[Bryan McQuade, 2015/09/04 20:53:17]

can we add:
// We may receive notifications from frames that have been navigated away
// from. We simply ignore them.
if (!IsCurrentMainFrame(render_frame_host))
  return false;

you'll need to implement IsCurrentMainFrame as something like:
return render_frame_host == web_contents()->GetMainFrame();
and you may wish to allow overriding it for the purposes of mocking it in tests,
so the unit tests can continue to work with a null web_contents.

[Bryan McQuade, 2015/09/04 20:53:17]

maybe change to "See comment in IsRelevantNavigation about..."

+  if (!GetLastCommittedURL().SchemeIsHTTPOrHTTPS())
+    return;
+
+  // Throw away IPCs that are not relevant to the current navigation.
+  if (PageLoadTimingIsChild(timing, *current_timing_)) {

[Bryan McQuade, 2015/09/04 20:53:17]

given that this is the only place we do this 'is child' test, I'm inclined to
just inline the implementation here. it'll be clearer overall to readers - they
can see what it means to be a child right here in the implementation, rather
than having to scroll up to check the implementation.

related: i'd make this another early return path:

if (!current_timing_->navigation_start.is_null() &&
    current_timing_->navigation_start != timing.navigation_start) {
  // UMA log a counter every time this happens.
  return;
}

Also, regarding logging errors in UMA, since there are a few other types of
errors that I think we also want to record, I've seen other similar code that
defines an enum of errors, and then uses the enum value as the bucket when uma
logging. there's an uma macro designed to be used with enum values.

+    if (current_timing_->IsEmpty())
+      current_host_ = render_frame_host;

[Bryan McQuade, 2015/09/04 20:53:17]

seems like the canonical source for the current render frame host should
probably be web_contents()->GetMainFrame(). Any reason we can't use that (or a
virtual bool IsCurrentMainFrame(...) if you want to override in tests)

[Charlie Harrison, 2015/09/08 23:05:14]

Which side of the equality would you propose changing to GetMainFrame()? I was
keeping track of current_host_ to sanity check that our hosts were not changing 
without our knowing it. It seems reasonable to compare that with the host we are
receiving messages from.

+    else
+      DCHECK(render_frame_host == current_host_);

[Bryan McQuade, 2015/09/04 20:53:17]

IIRC creis said that this can actually happen sometimes, when an old renderer
that has been navigated away from browser side sends IPCs. if that's the case,
then we don't want to DCHECK it.

[Charlie Harrison, 2015/09/08 23:05:15]

Shouldn't that be handled by the !IsCurrentMainFrame check? 

+    current_timing_.reset(new PageLoadTiming(timing));

[Bryan McQuade, 2015/09/04 20:53:17]

can you simplify to:
*current_timing_ = timing;

[Charlie Harrison, 2015/09/08 23:05:15]

Done.

+  }
+}
+
+void WebContentsObserver::RecordTimingHistograms() {
+  if (!current_timing_ || current_timing_->IsEmpty())
+    return;
+  else if (PageLoadTimingIsComplete(*current_timing_))

[Bryan McQuade, 2015/09/04 20:53:17]

testing validiting of the PageLoadHistograms seems really valuable. instead of
only testing ordering if it's complete, I suggest that we always validate as
much of the PageLoadTiming as we can, even if not complete. Things to validate:

bool IsValidPageLoadTiming(const PageLoadTiming& timing) {
  if (timing.IsEmpty())
    return true;

  // If we have a non-empty timing, it should always have a navigation_start.
  if (timing.navigation_start.is_null())
    return false;

  // If we have a dom content loaded event, we should have a response start.
  if (!timing.dom_content_loaded_event_start.is_zero()) {
    if (timing.response_start.is_zero())
      return false;
  }

  // If we have a load event, we should have both a response start and a DCL.
  if (!timing.load_event_start.is_zero()) {
    if (timing.response_start.is_zero() ||
        timing.dom_content_loaded_event_start.is_zero())
      return false;
  }

  return true;
}

and then at the call site, we should do something like:
if (!IsValidTiming(*current_timing_)) {
  // UMA log that we encountered an invalid timing.
  return;
}

[Bryan McQuade, 2015/09/08 14:09:46]

oh, and I forgot, we should also test ordering between the different entries
that are expected to be ordered relative to each other, as you had done in
PageLoadTimingIsOrdered.

[Charlie Harrison, 2015/09/08 23:05:15]

Is a PageLoadTiming with null nav_start really valid?

+    DCHECK(PageLoadTimingIsOrdered(*current_timing_));
+
+  if (!current_timing_->dom_content_loaded_event_start.is_zero()) {
+    PAGE_LOAD_HISTOGRAM("PageLoad.Timing.DOMContentLoadedEventFired",
+                        current_timing_->dom_content_loaded_event_start);
+  }
+
+  if (!current_timing_->load_event_start.is_zero()) {
+    PAGE_LOAD_HISTOGRAM("PageLoad.Timing.LoadEventFired",
+                        current_timing_->load_event_start);
+  }
+
+  if (!current_timing_->first_layout.is_zero()) {
+    PAGE_LOAD_HISTOGRAM("PageLoad.Timing.FirstLayout",
+                        current_timing_->first_layout);
+  }
+  current_timing_.reset();
+}
+
+bool WebContentsObserver::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 wan't to be
+  // sure here that we aren't logging UMA for internal pages
+  const GURL& browser_url = GetLastCommittedURL();
+  return navigation_handle->IsInMainFrame() &&
+      !navigation_handle->IsSamePage() &&
+      navigation_handle->HasCommittedDocument() &&
+      navigation_handle->GetURL().SchemeIsHTTPOrHTTPS() &&
+      browser_url.SchemeIsHTTPOrHTTPS();
+}
+
+const GURL& WebContentsObserver::GetLastCommittedURL() {
+  return web_contents()->GetLastCommittedURL();
+}
+
+}  // namespace page_load_metrics