Changes PlzNavitate histograms to try and simplify their multi-modal characteristic.

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"
@@ skipping 159 matching lines @@
   } else {
     params->redirects.clear();
   }
 
   params->can_load_local_resources = entry.GetCanLoadLocalResources();
   params->frame_to_navigate = entry.GetFrameToNavigate();
 }
 
 }  // namespace
 
+NavigatorImpl::NavigationMetricsData::NavigationMetricsData(
+    base::TimeTicks start_time, GURL url) : start_time_(start_time), url_(url) {

[nasko, 2014/10/08 17:10:42]

Please use clang-format/git cl format or keep to the style guide.
Parameters should be on their own lines. Same with initializers.

[carlosk, 2014/10/09 16:53:45]

Done! I had tried to run those tools before but only today I was finally able
to. I was doing the updating of my local tree the wrong way and had some broken
tools as a consequence.

+}
+
+void NavigatorImpl::NavigationMetricsData::Reset() {
+  start_time_ = base::TimeTicks();
+  url_ = GURL();
+  url_job_start_time_ = base::TimeTicks();
+  before_unload_delay_ = base::TimeDelta();
+}
+
+bool NavigatorImpl::NavigationMetricsData::IsTracking() {
+  return ! start_time_.is_null();

[nasko, 2014/10/08 17:10:42]

nit: no need for space between ! and start_time_.

[carlosk, 2014/10/09 16:53:45]

Done.

+}
+
 
 NavigatorImpl::NavigatorImpl(
     NavigationControllerImpl* navigation_controller,
     NavigatorDelegate* delegate)
     : controller_(navigation_controller),
       delegate_(delegate) {
 }
 
 NavigatorImpl::~NavigatorImpl() {}
 
@@ skipping 162 matching lines @@
   // "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();
 
   RenderFrameHostManager* manager =
       render_frame_host->frame_tree_node()->render_manager();
 
   // PlzNavigate: the RenderFrameHosts are no longer asked to navigate.
   if (CommandLine::ForCurrentProcess()->HasSwitch(
       switches::kEnableBrowserSideNavigation)) {
-    navigation_start_time_and_url = MakeTuple(navigation_start, entry.GetURL());
+    navigation_data = NavigatorImpl::NavigationMetricsData(
+        navigation_start, entry.GetURL());
     return RequestNavigation(render_frame_host->frame_tree_node(),
                              entry,
                              reload_type,
                              navigation_start);
   }
 
   RenderFrameHostImpl* dest_render_frame_host = manager->Navigate(entry);
   if (!dest_render_frame_host)
     return false;  // Unable to create the desired RenderFrameHost.
 
@@ skipping 18 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_and_url = MakeTuple(navigation_start, entry.GetURL());
+    navigation_data = NavigatorImpl::NavigationMetricsData(
+        navigation_start, 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 152 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): 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());
-  }
+  RecordNavigationMetrics(details, params, site_instance);
 
   // Run post-commit tasks.
   if (delegate_) {
     if (details.is_main_frame)
       delegate_->DidNavigateMainFramePostCommit(details, params);
 
     delegate_->DidNavigateAnyFramePostCommit(
         render_frame_host, details, params);
   }
 }
@@ skipping 176 matching lines @@
   NavigationRequest* navigation_request =
       navigation_request_map_.get(frame_tree_node->frame_tree_node_id());
   if (!navigation_request)
     return;
   navigation_request->CancelNavigation();
   navigation_request_map_.erase(frame_tree_node->frame_tree_node_id());
 }
 
 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);
+  if (navigation_data.IsTracking() && navigation_data.url_ == url) {
+    navigation_data.url_job_start_time_ = timestamp;
   }
 }
 
+void NavigatorImpl::LogBeforeUnloadTime(
+    const base::TimeTicks& renderer_before_unload_start_time,
+    const base::TimeTicks& renderer_before_unload_end_time) {
+  // Only stores the beforeunload delay if we're tracking the navigation and it
+  // happened later than the navigation request
+  if (navigation_data.IsTracking()
+      && renderer_before_unload_start_time > navigation_data.start_time_) {
+    navigation_data.before_unload_delay_ =
+      renderer_before_unload_end_time - renderer_before_unload_start_time;
+  }
+}
+
 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) {
@@ skipping 46 matching lines @@
   }
 
   // The navigation request is sent directly to the IO thread.
   OnBeginNavigation(
       frame_tree_node,
       MakeDefaultBeginNavigation(request_params, navigation_type),
       navigation_request_map_.get(frame_tree_node_id)->common_params());
   return true;
 }
 
+void NavigatorImpl::RecordNavigationMetrics(
+    const LoadCommittedDetails& details,
+    const FrameHostMsg_DidCommitProvisionalLoad_Params& params,
+    SiteInstance* site_instance) {
+  DCHECK(site_instance->HasProcess());
+  if (details.is_main_frame
+      && navigation_data.IsTracking()
+      && navigation_data.url_ == params.original_request_url) {
+
+    base::TimeDelta time_to_commit =
+        base::TimeTicks::Now() - navigation_data.start_time_;
+    UMA_HISTOGRAM_TIMES("Navigation.TimeToCommitRaw", time_to_commit);
+    base::TimeDelta time_to_network =
+        navigation_data.url_job_start_time_ - navigation_data.start_time_;
+    UMA_HISTOGRAM_TIMES("Navigation.TimeToURLJobStartRaw", time_to_network);
+
+    time_to_commit -= navigation_data.before_unload_delay_;
+    time_to_network -= navigation_data.before_unload_delay_;
+    bool spawned_new_process =
+      site_instance->GetProcess()->GetInitTime() > navigation_data.start_time_;

[nasko, 2014/10/08 17:10:42]

Is there a different way to judge this? I'd rather not add this method to
RenderProcessHostImpl, if possible.

[carlosk, 2014/10/09 16:53:45]

What I'm trying to separate here are navigations that did or did not caused the
creation of a new renderer process as consequentially the former takes longer
than the latter what should be the reason we're seeing a clearly bi-modal
histogram.

Comparing the navigation start time with the renderer process spawn time -- from
the one that was finally assigned to that navigation -- was the simplest and
surest method I could think for doing this. Can you think of another way of
finding that out?

I could also:
* try and find if there's a way of getting that information from the SO's
process data but this would possibly lead to more complicated, multi-platform
code.
* Remove that method from the RenderProcessHost interface but then have to do a
cast to RenderProcessHostImpl when I get it.

[clamy, 2014/10/09 19:02:32]

I think you could easily distinguish between the cases of a cross-process
navigation, or one where the renderer was not live, and same-process navigations
where the renderer is live. Granted for cross-process we may not end up creating
a new renderer, but there should be a fairly good chance that we do, right?

[carlosk, 2014/10/10 10:00:03]

As we're trying to eliminate the bi-modality this causes I am looking for a "for
sure" method: no guessing, no mistakes. That's why comparing timestamps seemed
like a sure and simple way to go.

The difference I see here is that trying to figure that out before the
navigation is impossible as it's exactly the same problem that leads us to
*speculative* spawn a new renderer for PlzNavigate.

On the other hand I didn't know what are the post-navigation evidences that I
could track that would tell me for sure that the navigation that just happened
spawned or didn't spawn a new renderer. Do they exist?

[clamy, 2014/10/10 19:59:12]

No that I know of. In any case, I am not sure we would be able to eliminate the
bi-modality there. I also don't think that figuring that out before the
navigation is impossible. This is different from PlzNavigate, in that the
RenderFrameHost that we chose in NavigatorImpl::NavigateToEntry is the one that
_will be used_ all the time. In PlzNavigate, we are basically betting that the
redirects won't get us to a different site instance, and so that whatever we
create before the navigation will still be valid when the navigation can commit,
hence the "speculative" name.

[carlosk, 2014/10/13 14:05:50]

Indeed we might not be able to eliminate the bi/multi modality. I'm just trying
to split things up so that we can try and figure out why for instance 30% of
TimeToCommit are taking above 1s in Windows machines.

Yes, indeed it seems I should be able to figure out the did/didn't spawn a new
renderer other ways -- apparently simpler with the current navigation
implementation -- but it'd be a) more complicated nonetheless and b) it would
have to be dealt differently for the current implementation and for PlzNavigate.

I just think comparing time stamps is dead simple, always corrent and now
invisible form other "packages" (as I did the change Nasko asked for a hid it
from the public RPH interface).

+    if (spawned_new_process) {
+      UMA_HISTOGRAM_TIMES("Navigation.TimeToCommitNewRenderer", time_to_commit);
+      UMA_HISTOGRAM_TIMES(
+        "Navigation.TimeToURLJobStartNewRenderer", time_to_network);
+    } else {
+      UMA_HISTOGRAM_TIMES("Navigation.TimeToCommitOldRenderer", time_to_commit);
+      UMA_HISTOGRAM_TIMES(
+        "Navigation.TimeToURLJobStartOldRenderer", time_to_network);
+    }
+
+    navigation_data.Reset();
+  }
+}
+
 }  // namespace content