Add time-to-network histogram considering browser side navigation

content/browser/frame_host/navigator_impl.cc

Index: content/browser/frame_host/navigator_impl.cc
diff --git a/content/browser/frame_host/navigator_impl.cc b/content/browser/frame_host/navigator_impl.cc
index 384bceeafbe37a8ccaab4546a517d86c8df019d1..87d62f6d11839a7fb6d31ce359eccb199a63d8db 100644
--- a/content/browser/frame_host/navigator_impl.cc
+++ b/content/browser/frame_host/navigator_impl.cc
@@ -5,6 +5,7 @@
 #include "content/browser/frame_host/navigator_impl.h"
 
 #include "base/command_line.h"
+#include "base/metrics/histogram.h"
 #include "base/time/time.h"
 #include "content/browser/frame_host/frame_tree.h"
 #include "content/browser/frame_host/frame_tree_node.h"
@@ -351,6 +352,8 @@ bool NavigatorImpl::NavigateToEntry(
   // node.
   if (CommandLine::ForCurrentProcess()->HasSwitch(
       switches::kEnableBrowserSideNavigation)) {
+    navigation_start_time_ = navigation_start;
+    navigation_start_url_ = entry.GetURL();
     // Create the navigation parameters.
     MakeNavigateParams(
         entry, *controller_, reload_type, navigation_start, &navigate_params);
@@ -388,6 +391,8 @@ bool NavigatorImpl::NavigateToEntry(
       navigate_params.transferred_request_child_id ==
           dest_render_frame_host->GetProcess()->GetID();
   if (!is_transfer_to_same) {
+    navigation_start_time_ = navigation_start;
+    navigation_start_url_ = entry.GetURL();
     dest_render_frame_host->Navigate(navigate_params);
   } else {
     // No need to navigate again.  Just resume the deferred request.
@@ -549,6 +554,19 @@ void NavigatorImpl::DidNavigate(
   // DidNavigateMainFramePostCommit / DidNavigateAnyFramePostCommit (only if
   // necessary, please).
 
+  // TODO(carlosk): Yes I did read the above comment and I will move this out
+  // of here as soon as I can a) get the information I need through
+  // WebContentsObserver and b) fix the current PlzNavigate implementation so
+  // that the observer methods are actually called.

[clamy, 2014/09/23 21:54:07]

If you don't implement the histograms as an observer, I would rephrase this
comment as
TODO(carlosk): Move this out when PlzNavigate implementation properly calls the
observer methods.

Alternatively, having PlzNavigate call the observer method for
AboutToNavigateRenderView should be fairly simple. The problem there will be the
plumbing required to get the network start time to the implementation of
WebContentsObserver used to record the histograms.

[carlosk, 2014/09/24 18:35:49]

I'll rephrase that to what you suggested.

Some notes on the change to a WCO implementation:
* Yes, changing is simple and allows us not to have to worry about matching with
the requests when what we need is offered by the WCO API.
* And yes the problem is the network start time because we'd need another way of
getting it (as we have now) and for that specific case we will need to do the
matching with the request anyway
* Finally the main reason I'm leaving this for later is because I think what I
added isn't too much stuff (arguably, this CR will confirm or counter this
point) and that currently the PlzNavigate work on eagerly spawning the rendered
in parallel was considered more important

+  if (details.is_main_frame &&

[nasko, 2014/09/24 00:48:06]

Do we only care about top-level navigations?

[carlosk, 2014/09/24 18:35:50]

Yes, from my talks with Camille. I still can't argue much in these cases but I
assume top level navigation offer a more suitable use case to checkout the
PlzNavigate improvements as for instance I guess non-top ones will never spawn a
new renderer?

[nasko, 2014/09/26 00:10:35]

Not yet, but in the not so long distant future they will : ).

[clamy, 2014/09/26 14:48:32]

Though not on Android right? Since the delay we observe is mainly on Android, I
think taking into account only the top level navigations may not be such an
issue.

[carlosk, 2014/09/26 15:50:25]

Acknowledged.

+      navigation_start_time_.ToInternalValue() != 0
+      && navigation_start_url_ == params.original_request_url) {
+    base::TimeDelta time_to_network =

[nasko, 2014/09/24 00:48:06]

Why is this named "time_to_network"? I don't see much networking here.

[carlosk, 2014/09/24 18:35:50]

Done! Bad copy-paste skills! :)

+      base::TimeTicks::Now() - navigation_start_time_;

[nasko, 2014/09/24 00:48:06]

nit: wrong indent

[carlosk, 2014/09/24 18:35:49]

Done! I assumed I was missing an extra couple of spaces?

[nasko, 2014/09/24 23:11:20]

Yes. In general, clang-format is your friend for almost all formatting needs :
).

[carlosk, 2014/09/25 17:26:05]

Didn't know about it and I'm having issues trying to run it locally. I'll figure
it out later...

+    UMA_HISTOGRAM_TIMES("Navigation.TimeToNavigationFinished", time_to_network);

[clamy, 2014/09/23 21:54:07]

I would rename this Navigation.TimeToCommit.

[nasko, 2014/09/24 00:48:06]

+1. I'd rename the TimeDelta variable also to match this.

[carlosk, 2014/09/24 18:35:50]

Done!

I had it named that way because this happens in the DidNavigate method which
comes *after* the CommitNavigation call. It seemed something "post commit".

[carlosk, 2014/09/24 18:35:50]

Done.

[nasko, 2014/09/24 23:11:21]

I think you have a bit of a misconception of start, commit, finish events. It
took me forever to figure out at the beginning, so I'd be happy to hop on chat
and help clarify those.

[carlosk, 2014/09/25 17:26:05]

Acknowledged. I'll take your teaching offer! :)

+    navigation_start_time_ = base::TimeTicks();
+  }
+
   // Run post-commit tasks.
   if (delegate_) {
     if (details.is_main_frame)
@@ -670,6 +688,20 @@ void NavigatorImpl::CommitNavigation(
       render_frame_host, info.navigation_url);
   // TODO(clamy): the render_frame_host should now send a commit IPC to the
   // renderer.
+  // TODO(carlosk): when Issue 376015 done (CL 519533002) use the

[nasko, 2014/09/24 00:48:06]

Instead of using "issue XXXXXX", use http://crbug.com/XXXXXX, which allows us to
link directly to the bug. Also, avoid putting CL numbers, since those are a lot
more volatile. One can open the bug and look at the recorded CL to get to it.

[carlosk, 2014/09/24 18:35:49]

Done.

[nasko, 2014/09/24 23:11:20]

And by "done" you mean "I've removed it, so it is no longer there"?

[carlosk, 2014/09/25 17:26:05]

Yes I removed the full comment as it was applicable only for PlzNavigate (see in
Patch Set 8).

+  // ResourceResponseInfo::request_time that will be made available here as the
+  // time stamp for time-to-network and replace the more convoluted way it's

[nasko, 2014/09/24 00:48:06]

nit: timestamp

[carlosk, 2014/09/24 18:35:49]

Done.

+  // being done right now (through the LogResourceRequestTime call below invoked
+  // from RDHI).
+}
+
+void NavigatorImpl::LogResourceRequestTime(
+    base::TimeTicks timestamp, const GURL& url) {
+  if (navigation_start_time_.ToInternalValue() != 0
+      && navigation_start_url_ == url) {
+    base::TimeDelta time_to_network = timestamp - navigation_start_time_;
+    UMA_HISTOGRAM_TIMES("Navigation.TimeToURLJobStart", time_to_network);
+  }
 }
 
 void NavigatorImpl::CheckWebUIRendererDoesNotDisplayNormalURL(