[startup metrics] Do not track initially hidden window and check navigation steps.

Prior to this CL, Startup.FirstWebContents.NonEmptyPaint2 was recorded for the
active WebContents in the first browser of the BrowserList. However, tests
highlighted that the first browser is not necessarily visible in session restore.
This CL changes the behavior to instead record
Startup.FirstWebContents.NonEmptyPaint2 for the active WebContents in the
first *visible* browser. It also adds a FinishReason for when no browser is
initially visible. This would allow us to track if there is a change in how often
Chrome starts with no initially visible browser (e.g. if this CL lands
https://chromium-review.googlesource.com/c/chromium/src/+/1888405/3/chrome/browser/sessions/session_restore.cc#477
we would start more often with no initially visible browser).

This CL also adds some DCHECKs to make sure that navigation events occur in the
order expected by FirstWebContentsProfiler.

Bug: 1020549
Change-Id: I0733a2b5af2f3617102232e9996459ad3b1c4c5b
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1894417Reviewed-by: Gabriel Charette <gab@chromium.org>
Commit-Queue: François Doray <fdoray@chromium.org>
Cr-Commit-Position: refs/heads/master@{#713192}

chrome/browser/metrics/first_web_contents_profiler.cc

@@ -14,8 +14,11 @@
 #include "build/build_config.h"
 #include "chrome/browser/ui/browser.h"
 #include "chrome/browser/ui/browser_list.h"
+#include "chrome/browser/ui/browser_window.h"
 #include "chrome/browser/ui/tabs/tab_strip_model.h"
 #include "components/startup_metric_utils/browser/startup_metric_utils.h"
+#include "content/public/browser/navigation_controller.h"
+#include "content/public/browser/navigation_entry.h"
 #include "content/public/browser/navigation_handle.h"
 #include "content/public/browser/render_frame_host.h"
 #include "content/public/browser/render_process_host.h"
@@ -24,34 +27,56 @@
 
 namespace {
 
+// Reasons for which profiling is deemed complete. Logged in UMA (do not re-
+// order or re-assign).
+enum class FinishReason {
+  // All metrics were successfully gathered.
+  kDone = 0,
+  // Abandon if blocking UI was shown during startup.
+  kAbandonBlockingUI = 1,
+  // Abandon if the WebContents is hidden (lowers scheduling priority).
+  kAbandonContentHidden = 2,
+  // Abandon if the WebContents is destroyed.
+  kAbandonContentDestroyed = 3,
+  // Abandon if the WebContents navigates away from its initial page.
+  kAbandonNewNavigation = 4,
+  // Abandon if the WebContents fails to load (e.g. network error, etc.).
+  kAbandonNavigationError = 5,
+  // Abandon if no WebContents was visible at the beginning of startup
+  kAbandonNoInitiallyVisibleContent = 6,
+  kMaxValue = kAbandonNoInitiallyVisibleContent
+};
+
+void RecordFinishReason(FinishReason finish_reason) {
+  UMA_HISTOGRAM_ENUMERATION("Startup.FirstWebContents.FinishReason",
+                            finish_reason);
+}
+
 class FirstWebContentsProfiler : public content::WebContentsObserver {
  public:
   FirstWebContentsProfiler(content::WebContents* web_contents,
                            startup_metric_utils::WebContentsWorkload workload);
 
  private:
-  // Reasons for which profiling is deemed complete. Logged in UMA (do not re-
-  // order or re-assign).
-  enum FinishReason {
-    // All metrics were successfully gathered.
-    DONE = 0,
-    // Abandon if blocking UI was shown during startup.
-    ABANDON_BLOCKING_UI = 1,
-    // Abandon if the content is hidden (lowers scheduling priority).
-    ABANDON_CONTENT_HIDDEN = 2,
-    // Abandon if the content is destroyed.
-    ABANDON_CONTENT_DESTROYED = 3,
-    // Abandon if the WebContents navigates away from its initial page.
-    ABANDON_NEW_NAVIGATION = 4,
-    // Abandon if the WebContents fails to load (e.g. network error, etc.).
-    ABANDON_NAVIGATION_ERROR = 5,
-    ENUM_MAX
+  // Steps of main frame navigation in a WebContents.
+  enum class NavigationStep {
+    // DidStartNavigation() is invalid
+    // DidFinishNavigation() transitions to kNavigationFinished
+    // DidFirstVisuallyNonEmptyPaint() is invalid
+    kNavigationStarted,
+
+    // DidStartNavigation() stops profiling with kAbandonNewNavigation
+    // DidFinishNavigation() is invalid
+    // DidFirstVisuallyNonEmptyPaint() stops profiling with kDone
+    kNavigationFinished,
   };
 
   ~FirstWebContentsProfiler() override = default;
 
   // content::WebContentsObserver:
   void DidFirstVisuallyNonEmptyPaint() override;
+  void DidStartNavigation(
+      content::NavigationHandle* navigation_handle) override;
   void DidFinishNavigation(
       content::NavigationHandle* navigation_handle) override;
   void OnVisibilityChanged(content::Visibility visibility) override;
@@ -60,11 +85,8 @@ class FirstWebContentsProfiler : public content::WebContentsObserver {
   // Logs |finish_reason| to UMA and deletes this FirstWebContentsProfiler.
   void FinishedCollectingMetrics(FinishReason finish_reason);
 
-  // Whether an attempt was made to collect the "MainNavigationStart/Finished"
-  // metrics.
-  bool collected_main_navigation_metrics_;
-
   const startup_metric_utils::WebContentsWorkload workload_;
+  NavigationStep navigation_step_ = NavigationStep::kNavigationStarted;
 
   DISALLOW_COPY_AND_ASSIGN(FirstWebContentsProfiler);
 };
@@ -72,13 +94,17 @@ class FirstWebContentsProfiler : public content::WebContentsObserver {
 FirstWebContentsProfiler::FirstWebContentsProfiler(
     content::WebContents* web_contents,
     startup_metric_utils::WebContentsWorkload workload)
-    : content::WebContentsObserver(web_contents),
-      collected_main_navigation_metrics_(false),
-      workload_(workload) {}
+    : content::WebContentsObserver(web_contents), workload_(workload) {
+  // FirstWebContentsProfiler is always created with a WebContents that started
+  // but did not finish navigating.
+  DCHECK(web_contents->GetController().GetPendingEntry());
+}
 
 void FirstWebContentsProfiler::DidFirstVisuallyNonEmptyPaint() {
+  DCHECK_EQ(navigation_step_, NavigationStep::kNavigationFinished);
+
   if (startup_metric_utils::WasMainWindowStartupInterrupted()) {
-    FinishedCollectingMetrics(FinishReason::ABANDON_BLOCKING_UI);
+    FinishedCollectingMetrics(FinishReason::kAbandonBlockingUI);
     return;
   }
 
@@ -88,42 +114,48 @@ void FirstWebContentsProfiler::DidFirstVisuallyNonEmptyPaint() {
                                   ->GetProcess()
                                   ->GetInitTimeForNavigationMetrics());
 
-  FinishedCollectingMetrics(FinishReason::DONE);
+  FinishedCollectingMetrics(FinishReason::kDone);
 }
 
-void FirstWebContentsProfiler::DidFinishNavigation(
+void FirstWebContentsProfiler::DidStartNavigation(
     content::NavigationHandle* navigation_handle) {
-  if (collected_main_navigation_metrics_) {
-    // Abandon profiling on a top-level 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.
-    //
-    // TODO(https://crbug.com/1020549): Determine whether
-    // Startup.FirstWebContents.NonEmptyPaint2 can be recorded for a non-initial
-    // navigation if there are multiple DidStartNavigation() before the first
-    // paint.
-    if (navigation_handle->IsInMainFrame() &&
-        navigation_handle->HasCommitted() &&
-        !navigation_handle->IsSameDocument()) {
-      FinishedCollectingMetrics(FinishReason::ABANDON_NEW_NAVIGATION);
-    }
+  // Ignore subframe navigations and same-document navigations.
+  if (!navigation_handle->IsInMainFrame() ||
+      navigation_handle->IsSameDocument()) {
     return;
   }
 
-  if (startup_metric_utils::WasMainWindowStartupInterrupted()) {
-    FinishedCollectingMetrics(FinishReason::ABANDON_BLOCKING_UI);
+  // DidFinishNavigation() should have been called to finish the preceding
+  // navigation.
+  DCHECK_EQ(navigation_step_, NavigationStep::kNavigationFinished);
+
+  // Abandon profiling on a top-level navigation to a different page as it:
+  //   (1) is no longer a fair timing; and
+  //   (2) can cause http://crbug.com/525209 where the 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.
+  FinishedCollectingMetrics(FinishReason::kAbandonNewNavigation);
+}
+
+void FirstWebContentsProfiler::DidFinishNavigation(
+    content::NavigationHandle* navigation_handle) {
+  // Ignore subframe navigations and same-document navigations.
+  if (!navigation_handle->IsInMainFrame() ||
+      navigation_handle->IsSameDocument()) {
     return;
   }
 
-  // The first navigation has to be the main frame's.
-  DCHECK(navigation_handle->IsInMainFrame());
+  DCHECK_EQ(navigation_step_, NavigationStep::kNavigationStarted);
+  navigation_step_ = NavigationStep::kNavigationFinished;
 
   if (!navigation_handle->HasCommitted() ||
       navigation_handle->IsErrorPage()) {
-    FinishedCollectingMetrics(FinishReason::ABANDON_NAVIGATION_ERROR);
+    FinishedCollectingMetrics(FinishReason::kAbandonNavigationError);
+    return;
+  }
+
+  if (startup_metric_utils::WasMainWindowStartupInterrupted()) {
+    FinishedCollectingMetrics(FinishReason::kAbandonBlockingUI);
     return;
   }
 
@@ -131,7 +163,6 @@ void FirstWebContentsProfiler::DidFinishNavigation(
       navigation_handle->NavigationStart(), workload_);
   startup_metric_utils::RecordFirstWebContentsMainNavigationFinished(
       base::TimeTicks::Now());
-  collected_main_navigation_metrics_ = true;
 }
 
 void FirstWebContentsProfiler::OnVisibilityChanged(
@@ -139,18 +170,17 @@ void FirstWebContentsProfiler::OnVisibilityChanged(
   if (visibility != content::Visibility::VISIBLE) {
     // Stop profiling if the content gets hidden as its load may be
     // deprioritized and timing it becomes meaningless.
-    FinishedCollectingMetrics(FinishReason::ABANDON_CONTENT_HIDDEN);
+    FinishedCollectingMetrics(FinishReason::kAbandonContentHidden);
   }
 }
 
 void FirstWebContentsProfiler::WebContentsDestroyed() {
-  FinishedCollectingMetrics(FinishReason::ABANDON_CONTENT_DESTROYED);
+  FinishedCollectingMetrics(FinishReason::kAbandonContentDestroyed);
 }
 
 void FirstWebContentsProfiler::FinishedCollectingMetrics(
     FinishReason finish_reason) {
-  UMA_HISTOGRAM_ENUMERATION("Startup.FirstWebContents.FinishReason",
-                            finish_reason, FinishReason::ENUM_MAX);
+  RecordFinishReason(finish_reason);
   delete this;
 }
 
@@ -163,15 +193,25 @@ void BeginFirstWebContentsProfiling() {
 
   const BrowserList* browser_list = BrowserList::GetInstance();
 
-  const auto first_browser = browser_list->begin();
-  if (first_browser == browser_list->end())
+  Browser* visible_browser = nullptr;
+  for (Browser* browser : *browser_list) {
+    if (browser->window()->IsVisible()) {
+      visible_browser = browser;
+      break;
+    }
+  }
+
+  if (!visible_browser) {
+    RecordFinishReason(FinishReason::kAbandonNoInitiallyVisibleContent);
     return;
+  }
 
-  const TabStripModel* tab_strip = (*first_browser)->tab_strip_model();
+  const TabStripModel* tab_strip = visible_browser->tab_strip_model();
   DCHECK(!tab_strip->empty());
 
   content::WebContents* web_contents = tab_strip->GetActiveWebContents();
   DCHECK(web_contents);
+  DCHECK_EQ(web_contents->GetVisibility(), content::Visibility::VISIBLE);
 
   const bool single_tab = browser_list->size() == 1 && tab_strip->count() == 1;
 

tools/metrics/histograms/enums.xml

@@ -59579,6 +59579,9 @@ Called by update_net_trust_anchors.py.-->
   <int value="5"
       label="Abandoned because profiled content failed to load its main
              resource"/>
+  <int value="6"
+      label="Abandoned because no content was visible at the beginning of
+             startup"/>
 </enum>
 
 <enum name="StartupTemperature">