Add time-to-network histogram considering browser side navigation

content/browser/frame_host/navigator_impl.cc

 // Copyright 2013 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 "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"
 #include "content/browser/frame_host/navigation_before_commit_info.h"
 #include "content/browser/frame_host/navigation_controller_impl.h"
 #include "content/browser/frame_host/navigation_entry_impl.h"
 #include "content/browser/frame_host/navigator_delegate.h"
 #include "content/browser/frame_host/render_frame_host_impl.h"
 #include "content/browser/renderer_host/render_view_host_impl.h"
 #include "content/browser/site_instance_impl.h"
@@ skipping 326 matching lines @@
 
   FrameMsg_Navigate_Params navigate_params;
   RenderFrameHostManager* manager =
       render_frame_host->frame_tree_node()->render_manager();
 
   // PlzNavigate: the RenderFrameHosts are no longer asked to navigate. Instead
   // the RenderFrameHostManager handles the navigation requests for that frame
   // 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);
     return manager->RequestNavigation(entry, navigate_params);
   }
 
   RenderFrameHostImpl* dest_render_frame_host = manager->Navigate(entry);
   if (!dest_render_frame_host)
     return false;  // Unable to create the desired RenderFrameHost.
 
@@ skipping 17 matching lines @@
 
   // Navigate in the desired RenderFrameHost.
   // We can skip this step in the rare case that this is a transfer navigation
   // which began in the chosen RenderFrameHost, since the request has already
   // been issued.  In that case, simply resume the response.
   bool is_transfer_to_same =
       navigate_params.transferred_request_child_id != -1 &&
       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.
     dest_render_frame_host->GetProcess()->ResumeDeferredNavigation(
         GlobalRequestID(navigate_params.transferred_request_child_id,
                         navigate_params.transferred_request_request_id));
   }
 
   // Make sure no code called via RFH::Navigate clears the pending entry.
   CHECK_EQ(controller_->GetPendingEntry(), &entry);
@@ skipping 141 matching lines @@
   }
 
   if (!did_navigate)
     return;  // No navigation happened.
 
   // DO NOT ADD MORE STUFF TO THIS FUNCTION! Your component should either listen
   // for the appropriate notification (best) or you can add it to
   // 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)
       delegate_->DidNavigateMainFramePostCommit(details, params);
 
     delegate_->DidNavigateAnyFramePostCommit(
         render_frame_host, details, params);
   }
 }
 
@@ skipping 101 matching lines @@
     delegate_->RequestOpenURL(render_frame_host, params);
 }
 
 void NavigatorImpl::CommitNavigation(
     RenderFrameHostImpl* render_frame_host,
     const NavigationBeforeCommitInfo& info) {
   CheckWebUIRendererDoesNotDisplayNormalURL(
       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(
     RenderFrameHostImpl* render_frame_host,
     const GURL& url) {
   int enabled_bindings =
       render_frame_host->render_view_host()->GetEnabledBindings();
   bool is_allowed_in_web_ui_renderer =
       WebUIControllerFactoryRegistry::GetInstance()->IsURLAcceptableForWebUI(
           controller_->GetBrowserContext(), url);
   if ((enabled_bindings & BINDINGS_POLICY_WEB_UI) &&
       !is_allowed_in_web_ui_renderer) {
     // Log the URL to help us diagnose any future failures of this CHECK.
     GetContentClient()->SetActiveURL(url);
     CHECK(0);
   }
 }
 
 }  // namespace content