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

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 c74358bcadd1d19768fcee8e70b7d95ac3c16908..4b5b61af7ddb33c56bb7c7c25f4a95d4a954f727 100644
--- a/content/browser/frame_host/navigator_impl.cc
+++ b/content/browser/frame_host/navigator_impl.cc
@@ -177,6 +177,21 @@ void MakeNavigateParams(const NavigationEntryImpl& entry,
 
 }  // 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,
@@ -359,7 +374,8 @@ bool NavigatorImpl::NavigateToEntry(
   // 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,
@@ -398,7 +414,8 @@ 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());
+    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.
@@ -571,14 +588,7 @@ void NavigatorImpl::DidNavigate(
 
   // 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_) {
@@ -775,11 +785,20 @@ void NavigatorImpl::CancelNavigation(FrameTreeNode* frame_tree_node) {
 
 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;
   }
 }
 
@@ -849,4 +868,38 @@ bool NavigatorImpl::RequestNavigation(
   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