Add new histogram to assert the improvements we should get with browser side...

Add new histogram to assert the improvements we should get with browser side navigation (aka PlzNavigate).

Time measured:
* Time from navigation request to first network request
* Time from navigation request to navigation committed/finished

BUG=416877

Review URL: https://codereview.chromium.org/577963002

Cr-Commit-Position: refs/heads/master@{#297410}

content/browser/frame_host/navigator.h

@@ -6,6 +6,7 @@
 #define CONTENT_BROWSER_FRAME_HOST_NAVIGATOR_H_
 
 #include "base/memory/ref_counted.h"
+#include "base/time/time.h"
 #include "content/common/content_export.h"
 #include "content/public/browser/navigation_controller.h"
 #include "ui/base/window_open_disposition.h"
@@ -115,6 +116,11 @@ class CONTENT_EXPORT Navigator : public base::RefCounted<Navigator> {
   virtual void CommitNavigation(RenderFrameHostImpl* render_frame_host,
                                 const NavigationBeforeCommitInfo& info) {};
 
+  // Called when the first resource request for a given navigation is executed
+  // so that it can be tracked into an histogram.
+  virtual void LogResourceRequestTime(
+    base::TimeTicks timestamp, const GURL& url) {};
+
  protected:
   friend class base::RefCounted<Navigator>;
   virtual ~Navigator() {}

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"
@@ -81,6 +82,9 @@ NavigatorImpl::NavigatorImpl(
       delegate_(delegate) {
 }
 
+NavigatorImpl::~NavigatorImpl() {
+}
+
 // static.
 void NavigatorImpl::MakeNavigateParams(
     const NavigationEntryImpl& entry,
@@ -322,6 +326,7 @@ bool NavigatorImpl::NavigateToEntry(
   // node.
   if (CommandLine::ForCurrentProcess()->HasSwitch(
       switches::kEnableBrowserSideNavigation)) {
+    navigation_start_time_and_url = MakeTuple(navigation_start, entry.GetURL());
     // Create the navigation parameters.
     MakeNavigateParams(
         entry, *controller_, reload_type, navigation_start, &navigate_params);
@@ -359,6 +364,7 @@ bool NavigatorImpl::NavigateToEntry(
       navigate_params.transferred_request_child_id ==
           dest_render_frame_host->GetProcess()->GetID();
   if (!is_transfer_to_same) {
+    navigation_start_time_and_url = MakeTuple(navigation_start, entry.GetURL());
     dest_render_frame_host->Navigate(navigate_params);
   } else {
     // No need to navigate again.  Just resume the deferred request.
@@ -520,6 +526,17 @@ void NavigatorImpl::DidNavigate(
   // DidNavigateMainFramePostCommit / DidNavigateAnyFramePostCommit (only if
   // necessary, please).
 
+  // TODO(carlosk): Move this out when PlzNavigate implementation properly calls
+  // the observer methods.
+  if (details.is_main_frame &&
+      navigation_start_time_and_url.a.ToInternalValue() != 0
+      && navigation_start_time_and_url.b == params.original_request_url) {
+    base::TimeDelta time_to_commit =
+        base::TimeTicks::Now() - navigation_start_time_and_url.a;
+    UMA_HISTOGRAM_TIMES("Navigation.TimeToCommit", time_to_commit);
+    navigation_start_time_and_url = MakeTuple(base::TimeTicks(), GURL());
+  }
+
   // Run post-commit tasks.
   if (delegate_) {
     if (details.is_main_frame)
@@ -644,6 +661,16 @@ void NavigatorImpl::CommitNavigation(
   // renderer.
 }
 
+void NavigatorImpl::LogResourceRequestTime(
+    base::TimeTicks timestamp, const GURL& url) {
+  if (navigation_start_time_and_url.a.ToInternalValue() != 0
+      && navigation_start_time_and_url.b == url) {
+    base::TimeDelta time_to_network =
+        timestamp - navigation_start_time_and_url.a;
+    UMA_HISTOGRAM_TIMES("Navigation.TimeToURLJobStart", time_to_network);
+  }
+}
+
 void NavigatorImpl::CheckWebUIRendererDoesNotDisplayNormalURL(
     RenderFrameHostImpl* render_frame_host,
     const GURL& url) {

content/browser/frame_host/navigator_impl.h

@@ -6,9 +6,12 @@
 #define CONTENT_BROWSER_FRAME_HOST_NAVIGATOR_IMPL_H_
 
 #include "base/memory/ref_counted.h"
+#include "base/time/time.h"
+#include "base/tuple.h"
 #include "content/browser/frame_host/navigation_controller_impl.h"
 #include "content/browser/frame_host/navigator.h"
 #include "content/common/content_export.h"
+#include "url/gurl.h"
 
 struct FrameMsg_Navigate_Params;
 
@@ -73,8 +76,11 @@ class CONTENT_EXPORT NavigatorImpl : public Navigator {
       RenderFrameHostImpl* render_frame_host,
       const NavigationBeforeCommitInfo& info) OVERRIDE;
 
+  virtual void LogResourceRequestTime(
+      base::TimeTicks timestamp, const GURL& url) OVERRIDE;
+
  private:
-  virtual ~NavigatorImpl() {}
+  virtual ~NavigatorImpl();
 
   // Navigates to the given entry, which must be the pending entry.  Private
   // because all callers should use NavigateToPendingEntry.
@@ -99,6 +105,10 @@ class CONTENT_EXPORT NavigatorImpl : public Navigator {
   // events. Can be NULL in tests.
   NavigatorDelegate* delegate_;
 
+  // The start time and URL for latest navigation request, used for feeding a
+  // few histograms under the Navigation group.
+  Tuple2<base::TimeTicks, GURL> navigation_start_time_and_url;
+
   DISALLOW_COPY_AND_ASSIGN(NavigatorImpl);
 };
 

content/browser/frame_host/render_frame_host_manager_unittest.cc

@@ -5,6 +5,7 @@
 #include "base/command_line.h"
 #include "base/files/file_path.h"
 #include "base/strings/utf_string_conversions.h"
+#include "base/test/histogram_tester.h"
 #include "base/time/time.h"
 #include "content/browser/frame_host/cross_site_transferring_request.h"
 #include "content/browser/frame_host/navigation_before_commit_info.h"
@@ -1864,4 +1865,30 @@ TEST_F(RenderFrameHostManagerTest,
   EXPECT_EQ(kUrl2_site, main_test_rfh()->GetSiteInstance()->GetSiteURL());
 }
 
+// PlzNavigate: Tests that the navigation histograms are correctly tracked both
+// when PlzNavigate is enabled and disabled, and also ignores in-tab renderer
+// initiated navigation for the non-enabled case.
+// Note: the related histogram, Navigation.TimeToURLJobStart, cannot be tracked
+// by this test as the IO thread is not running.
+TEST_F(RenderFrameHostManagerTest, BrowserSideNavigationHistogramTest) {
+  const GURL kUrl0("http://www.google.com/");
+  const GURL kUrl1("http://www.chromium.org/");
+  base::HistogramTester histo_tester;
+
+  // Performs a "normal" non-PlzNavigate navigation
+  contents()->NavigateAndCommit(kUrl0);
+  histo_tester.ExpectTotalCount("Navigation.TimeToCommit", 1);
+
+  // Performs an in-tab renderer initiated navigation
+  int32 new_page_id = 1 + contents()->GetMaxPageIDForSiteInstance(
+      main_test_rfh()->GetSiteInstance());
+  main_test_rfh()->SendNavigate(new_page_id, kUrl0);
+  histo_tester.ExpectTotalCount("Navigation.TimeToCommit", 1);
+
+  // Performs a PlzNavigate navigation
+  EnableBrowserSideNavigation();
+  contents()->NavigateAndCommit(kUrl1);
+  histo_tester.ExpectTotalCount("Navigation.TimeToCommit", 2);
+}
+
 }  // namespace content

content/browser/loader/resource_dispatcher_host_impl.cc

@@ -32,6 +32,7 @@
 #include "content/browser/download/save_file_resource_handler.h"
 #include "content/browser/fileapi/chrome_blob_storage_context.h"
 #include "content/browser/frame_host/navigation_request_info.h"
+#include "content/browser/frame_host/navigator.h"
 #include "content/browser/loader/async_resource_handler.h"
 #include "content/browser/loader/buffered_resource_handler.h"
 #include "content/browser/loader/cross_site_resource_handler.h"
@@ -383,6 +384,24 @@ void AttachRequestBodyBlobDataHandles(
   }
 }
 
+// PlzNavigate
+// This method is called in the UI thread to send the timestamp of a resource
+// request to the respective Navigator (for an UMA histogram).
+void LogResourceRequestTimeOnUI(
+    base::TimeTicks timestamp,
+    int render_process_id,
+    int render_frame_id,
+    const GURL& url) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+  RenderFrameHostImpl* host =
+      RenderFrameHostImpl::FromID(render_process_id, render_frame_id);
+  if (host != NULL) {
+    DCHECK(host->frame_tree_node()->IsMainFrame());
+    host->frame_tree_node()->navigator()->LogResourceRequestTime(
+        timestamp, url);
+  }
+}
+
 }  // namespace
 
 // static
@@ -947,6 +966,19 @@ void ResourceDispatcherHostImpl::OnRequestResource(
     int routing_id,
     int request_id,
     const ResourceHostMsg_Request& request_data) {
+  // When logging time-to-network only care about main frame and non-transfer
+  // navigations.
+  if (request_data.resource_type == RESOURCE_TYPE_MAIN_FRAME &&
+      request_data.transferred_request_request_id == -1) {
+    BrowserThread::PostTask(
+        BrowserThread::UI,
+        FROM_HERE,
+        base::Bind(&LogResourceRequestTimeOnUI,
+                   TimeTicks::Now(),
+                   filter_->child_id(),
+                   request_data.render_frame_id,
+                   request_data.url));
+  }
   BeginRequest(request_id, request_data, NULL, routing_id);
 }
 

tools/metrics/histograms/histograms.xml

@@ -13730,6 +13730,22 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
+<histogram name="Navigation.TimeToCommit" units="milliseconds">
+  <owner>carlosk@chromium.org</owner>
+  <summary>
+    Time between the start of a navigation request in the browser and its
+    commit.
+  </summary>
+</histogram>
+
+<histogram name="Navigation.TimeToURLJobStart" units="milliseconds">
+  <owner>carlosk@chromium.org</owner>
+  <summary>
+    Time between the start of a navigation request in the browser and the
+    reception of a corresponding ResourceRequest in the network stack.
+  </summary>
+</histogram>
+
 <histogram name="NCN.CM.FastestRTTOn2G" units="milliseconds">
   <owner>pauljensen@chromium.org</owner>
   <summary>
@@ -38291,7 +38307,7 @@ Therefore, the affected-histogram name has to have at least one dot in it.
 <histogram name="WinTimeTicks.NonStopTsc">
   <owner>Please list the metric's owners. Add more owner tags as needed.</owner>
   <summary>
-    True if the CPU's time stamp counter ticks at a constant rate regardless of
+    True if the CPU's timestamp counter ticks at a constant rate regardless of
     CPU frequency.
   </summary>
 </histogram>