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 311 matching lines @@
   TRACE_EVENT0("browser,navigation", "NavigatorImpl::NavigateToEntry");
 
   // The renderer will reject IPC messages with URLs longer than
   // this limit, so don't attempt to navigate with a longer URL.
   if (entry.GetURL().spec().size() > GetMaxURLChars()) {
     LOG(WARNING) << "Refusing to load URL as it exceeds " << GetMaxURLChars()
                  << " characters.";
     return false;
   }
 
-  // This will be used to set the Navigation Timing API navigationStart
+  // This time will be used to set the Navigation Timing API navigationStart
   // parameter for browser navigations in new tabs (intents, tabs opened through
   // "Open link in new tab"). We need to keep it above RFHM::Navigate() call to
   // capture the time needed for the RenderFrameHost initialization.
-  base::TimeTicks navigation_start = base::TimeTicks::Now();
+  navigation_start_time_ = base::TimeTicks::Now();
+  LOG(WARNING) << "###########################";
+  LOG(WARNING) << "NAVIGATION STARTED AT " << navigation_start_time_.ToInternalValue();
+  LOG(WARNING) << "process_id / child_id = " << render_frame_host->GetProcess()->GetID();
+  LOG(WARNING) << "routing_id / render_frame_host = " << render_frame_host->routing_id();

[clamy, 2014/09/17 21:12:39]

You cannot use the id values for this render_frame_host because it is not
necessarily the one that is going to navigate. See further comments below.

[carlosk, 2014/09/18 15:00:52]

Acknowledged.

+  LOG(WARNING) << "URL = " << entry.GetURL();
 
   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)) {
     // Create the navigation parameters.
     MakeNavigateParams(
-        entry, *controller_, reload_type, navigation_start, &navigate_params);
+        entry, *controller_, reload_type, navigation_start_time_, &navigate_params);
     return manager->RequestNavigation(entry, navigate_params);
   }
 
   RenderFrameHostImpl* dest_render_frame_host = manager->Navigate(entry);

[clamy, 2014/09/17 21:12:39]

We pick here the RFH that is going to navigate. It will be different from
render_frame_host if we are doing a cross process navigation.

[carlosk, 2014/09/18 15:00:52]

Acknowledged.

   if (!dest_render_frame_host)
     return false;  // Unable to create the desired RenderFrameHost.
 
   // Make sure no code called via RFHM::Navigate clears the pending entry.
   CHECK_EQ(controller_->GetPendingEntry(), &entry);
 
   // For security, we should never send non-Web-UI URLs to a Web UI renderer.
   // Double check that here.
   CheckWebUIRendererDoesNotDisplayNormalURL(
       dest_render_frame_host, entry.GetURL());
 
   // Notify observers that we will navigate in this RenderFrame.
   if (delegate_)
     delegate_->AboutToNavigateRenderFrame(dest_render_frame_host);
 
   // Create the navigation parameters.
   // TODO(vitalybuka): Move this before AboutToNavigateRenderFrame once
   // http://crbug.com/408684 is fixed.
   MakeNavigateParams(
-      entry, *controller_, reload_type, navigation_start, &navigate_params);
+      entry, *controller_, reload_type, navigation_start_time_, &navigate_params);
 
   // 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) {
     dest_render_frame_host->Navigate(navigate_params);

[clamy, 2014/09/17 21:12:39]

And we have it navigate here...

[carlosk, 2014/09/18 15:00:52]

So you mean that it's only here -- right before the Navigate call -- that I
should store the navigation start time? And I should only do it if
is_transfer_to_same is true? And ignore if it's false?

   } 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 134 matching lines @@
           params.transition | PAGE_TRANSITION_FORWARD_BACK);
     }
 
     delegate_->DidCommitProvisionalLoad(render_frame_host,
                                         params.url,
                                         transition_type);
   }
 
   if (!did_navigate)
     return;  // No navigation happened.
 

[carlosk, 2014/09/18 15:00:52]

As there's this "no navigation happened" comment here I'm guessing I should only
register the navigation right after this point.

But... (see next comment)

   // 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).
 

[carlosk, 2014/09/18 15:00:52]

But it's said here nothing should be added to this method anymore... I think
this histogram work should be an exception to this rule as there is no other
"component" involved because it's NavigatorImpl itself who's handling this data.

   // Run post-commit tasks.
   if (delegate_) {
     if (details.is_main_frame)
       delegate_->DidNavigateMainFramePostCommit(details, params);
 
     delegate_->DidNavigateAnyFramePostCommit(
         render_frame_host, details, params);
   }
 }
 
@@ skipping 97 matching lines @@
 
 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.
 }
 
+void NavigatorImpl::LogResourceRequestTime(base::TimeTicks timestamp) {
+  base::TimeDelta time_to_network = base::TimeTicks::Now() - timestamp;

[clamy, 2014/09/17 21:12:40]

This should be timestamp - navigation_start_time_. Otherwise you are timing the
time it takes to post a task to the UI thread.

[carlosk, 2014/09/18 15:00:52]

Yes, of course! Done! 

+  LOG(WARNING) << "=======================";
+  LOG(WARNING) << "Time to network request: " << time_to_network.InMilliseconds();
+  LOCAL_HISTOGRAM_TIMES("PlzNavigate.TimeToNetworkRequest", 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