Add start/finish navigation to startup metrics.

chrome/browser/metrics/first_web_contents_profiler.cc

 // Copyright 2014 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.
 
 #if !defined(OS_ANDROID)
 
 #include "chrome/browser/metrics/first_web_contents_profiler.h"
 
 #include <string>
 
 #include "base/location.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/process/process_info.h"
 #include "base/single_thread_task_runner.h"
 #include "base/thread_task_runner_handle.h"
 #include "base/time/time.h"
 #include "chrome/browser/ui/browser.h"
 #include "chrome/browser/ui/browser_iterator.h"
 #include "chrome/browser/ui/tabs/tab_strip_model.h"
 #include "components/metrics/profiler/tracking_synchronizer.h"
 #include "components/metrics/proto/profiler_event.pb.h"
 #include "components/startup_metric_utils/startup_metric_utils.h"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/navigation_details.h"
+#include "content/public/browser/navigation_handle.h"
 
 namespace {
 
 // The initial delay for responsiveness prober in milliseconds.
 const int kInitialDelayMs = 20;
 
 // The following is the multiplier is used to delay the probe for
 // responsiveness.
 const double kBackoffMultiplier = 1.5;
 
@@ skipping 74 matching lines @@
     }
   }
 }
 
 FirstWebContentsProfiler::FirstWebContentsProfiler(
     content::WebContents* web_contents)
     : content::WebContentsObserver(web_contents),
       initial_entry_committed_(false),
       collected_paint_metric_(false),
       collected_load_metric_(false),
+      collected_main_navigation_start_metric_(false),
+      collected_main_navigation_finished_metric_(false),
+      collected_main_navigation_finished_all_metric_(false),
       responsiveness_histogram_(NULL),
       responsiveness_1sec_histogram_(NULL),
       responsiveness_10sec_histogram_(NULL),
       unresponsiveness_histogram_(NULL),
       unresponsiveness_1sec_histogram_(NULL),
       unresponsiveness_10sec_histogram_(NULL) {
   InitHistograms();
 }
 
+FirstWebContentsProfiler::~FirstWebContentsProfiler() {
+}
+
 void FirstWebContentsProfiler::DidFirstVisuallyNonEmptyPaint() {
   if (collected_paint_metric_)
     return;
   if (startup_metric_utils::WasNonBrowserUIDisplayed()) {
     FinishedCollectingMetrics(FinishReason::ABANDON_BLOCKING_UI);
     return;
   }
 
   collected_paint_metric_ = true;
   startup_metric_utils::RecordFirstWebContentsNonEmptyPaint(base::Time::Now());
@@ skipping 33 matching lines @@
     return;
   }
 
   collected_load_metric_ = true;
   startup_metric_utils::RecordFirstWebContentsMainFrameLoad(base::Time::Now());
 
   if (IsFinishedCollectingMetrics())
     FinishedCollectingMetrics(FinishReason::DONE);
 }
 
+void FirstWebContentsProfiler::DidStartNavigation(
+    content::NavigationHandle* navigation_handle) {
+  if (startup_metric_utils::WasNonBrowserUIDisplayed()) {
+    FinishedCollectingMetrics(FinishReason::ABANDON_BLOCKING_UI);
+    return;
+  }
+
+  if (!navigation_handle->IsInMainFrame())
+    return;
+
+  // Record that the navigation identified by |navigation_handle| has started.
+  // DidFinishNavigation() assumes that every |navigation_handle| seen here is a
+  // new navigation, assert that this is true.
+  bool new_navigation =
+      main_navigation_handles_.insert(navigation_handle).second;
+  DCHECK(new_navigation);
+
+  if (!collected_main_navigation_start_metric_) {
+    collected_main_navigation_start_metric_ = true;
+    startup_metric_utils::RecordFirstWebContentsMainNavigationStart(
+        base::Time::Now());
+  }
+}
+
+void FirstWebContentsProfiler::DidFinishNavigation(
+    content::NavigationHandle* navigation_handle) {
+  if (collected_main_navigation_finished_all_metric_)
+    return;
+
+  if (startup_metric_utils::WasNonBrowserUIDisplayed()) {
+    FinishedCollectingMetrics(FinishReason::ABANDON_BLOCKING_UI);
+    return;
+  }
+
+  if (!navigation_handle->IsInMainFrame())
+    return;

[clamy, 2015/10/22 17:21:07]

You may also need to check whether the navigation was aborted or not.
NavigationHandle::HasCommitted will tell you if the navigation committed. If you
need to distinguish between a successful commit and an error page commit, use
NavigationHandle::IsErrorPage.

[gab, 2015/10/22 20:37:39]

Good point, even added it as an explicit early exit criteria like some others we
already have in this file.

+
+  // Remove |navigation_handle| from the tracked |main_navigation_handles_|.
+  size_t handles_tracked = main_navigation_handles_.erase(navigation_handle);
+  DCHECK_EQ(handles_tracked, 1U);
+
+  // First navigation in main frame is complete.
+  if (!collected_main_navigation_finished_metric_) {
+    collected_main_navigation_finished_metric_ = true;
+    startup_metric_utils::RecordFirstWebContentsMainNavigationFinishedFirst(
+        base::Time::Now());
+  }
+
+  // All known navigations in main frame are complete.
+  if (main_navigation_handles_.empty()) {
+    collected_main_navigation_finished_all_metric_ = true;
+    startup_metric_utils::RecordFirstWebContentsMainNavigationFinishedAll(

[clamy, 2015/10/22 17:21:07]

I don't think this is really needed.

While it's true that there can be at most 2 ongoing navigations in the same
frame, the first one two commit will cancel the other one, exceptin one special
case. The special case is a non user-initiated same-site navigation (a
renderer-initiated one) will not cancel an ongoing cross-site navigation (which
is browser-initiated).

In the case of startup, you don't have a renderer with a page loaded in it so
the special case cannot happen. This means that all navigations will always
finish by the time the first of them commit (there are some subtleties if it's
the cross-site one that finishes first due to having to do a round-trip with the
renderer for the execution of the unload event, but we don't allow the same-site
navigation to commit during that time anyway, so the time difference you could
see between the two DidFinishNavigation is not meaningful).

Since you most likely don't need to check that all navigations are finished, you
don't need to store the NavigationHandles either, making this patch simpler :).

[gab, 2015/10/22 20:37:39]

Ah ok, maybe this should be made clearer in WebContentsObserver? i.e. from
someone that doesn't know anything about networking I was worried that this
could matter a lot (i.e.  I thought a "navigation" was to a single host and that
there were many per frame to gather all resources -- though now that I think
about it I guess the navigation brings back the main resource and then the
renderers figure out what other resources are needed from there?).

+        base::Time::Now());
+  }
+}
+
 void FirstWebContentsProfiler::NavigationEntryCommitted(
     const content::LoadCommittedDetails& load_details) {
   // Abandon profiling on any navigation to a different page as it:
   //   (1) is no longer a fair timing; and
   //   (2) can cause http://crbug.com/525209 where one of the timing heuristics
   //       (e.g. first paint) didn't fire for the initial content but fires
   //       after a lot of idle time when the user finally navigates to another
   //       page that does trigger it.
   if (load_details.is_navigation_to_different_page()) {
     if (initial_entry_committed_)
       FinishedCollectingMetrics(FinishReason::ABANDON_NAVIGATION);

[gab, 2015/10/22 20:37:39]

While I have your attention and expertise, WDYT of this? Is this the right
place/way to catch new navigations?

[clamy, 2015/10/26 17:51:42]

There could be an issue with client-side redirects. Conceptually, they belong to
the first navigation, so I don't think we want to discard collecting metrics if
we encounter one of those. I'm not familiar enough with the NavigationController
to know if we will get the notification in that case (creis@ is the persons who
knows best).

If we do get the notification, it may be possible to filter those out by
checking the NavigationType in the LoadCommittedDetails.

If this is not possible/desirable, I would suggest merging the code here with
the one in DidFinishNavigation since they will fire at the same point in time
for successful navigations.

[gab, 2015/10/27 15:56:15]

Thanks, +creis to chime in on details.

From what I understand (NavigationEntryCommitted() +
load_details.is_navigation_to_different_page()) would only kick in when the
history would be modified (i.e. new top-level navigation or back/forward history
interaction), is this correct?

I just tried this with a test URL (https://goo.gl/MznQ97 -- which points to this
review), launching locally with chrome.exe https://goo.gl/MznQ97 results in the
stats being collected (i.e. not unintentionally abandoned here).

(not a blocker for this CL as the code under discussion is already in, will
follow-up if needed)

[Charlie Reis, 2015/10/27 18:35:21]

You will get NavigationEntryCommitted for both the page that does a client
redirect and the destination page.  There will also be no indication that a
client redirect is coming, because that could be determined by script code at
runtime.  You probably just want to treat the first commit as the point you're
done.
You can get NavigationEntryCommitted and to_different_page for top-level
navigations and back/forwards.  Those aren't really equivalent, though. 
Top-level navigations and back/forwards can also cause same-page navigations (so
to_different_page() would be false).
Ah, that's a server redirect, which is a different case.  We don't commit any
navigation until after a server redirect occurs.

A client redirect means that one page actually commits, and it's then quickly
followed by a separate commit that replaces the first one's NavigationEntry.

Hope that helps.

[gab, 2015/10/28 01:55:12]

Well, we are collecting first commit, but we're also collecting first paint and
main frame load (and want to avoid collecting those if the user navigates again
before they occur as their occurence post-second-navigation would add a
user-inflicted delay in the metrics and wouldn't measure the right thing).
As long as it's true one-way I'm okay if it's not equivalent (it just means
there is another edge case where we could gather stats after a navigation which
we're trying to avoid but is already better with this code then without it).
I think that's okay. I don't think we can do much about client redirects. We'll
do our best to catch first paint and main frame load metrics but if the redirect
kicks in before we do, we indeed want to cancel gathering our metrics as, again,
the redirect inflicts unexpected noise in the rendering pipeline (in practice
though I would expect it to be very rare for a user's foreground tab upon
launching Chrome to be pointed at a URL with a client side redirect).
Thanks a lot, overall my assessment is that this does what we want (abandons
gathering metrics when a new top-level navigation is introduced in the rendering
pipeline of the first tab on browser startup -- by the user or by script).

     else
       initial_entry_committed_ = true;
   }
 }
 
 void FirstWebContentsProfiler::WasHidden() {
   // Stop profiling if the content gets hidden as its load may be deprioritized
   // and timing it becomes meaningless.
   FinishedCollectingMetrics(FinishReason::ABANDON_CONTENT_HIDDEN);
 }
@@ skipping 58 matching lines @@
       100, base::Histogram::kUmaTargetedHistogramFlag);
 
   const std::string unresponsiveness_10sec_histogram_name =
       "Startup.FirstWebContents.UINotResponsive_10sec";
   unresponsiveness_10sec_histogram_ = base::Histogram::FactoryTimeGet(
       unresponsiveness_10sec_histogram_name,
       base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromSeconds(60),
       100, base::Histogram::kUmaTargetedHistogramFlag);
 }
 #endif  // !defined(OS_ANDROID)