[Sessions] Add detailed logging of SessionRestore events.

chrome/browser/sessions/session_restore_stats_collector.cc

 // Copyright 2015 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 "chrome/browser/sessions/session_restore_stats_collector.h"
 
 #include <string>
 
 #include "base/metrics/histogram.h"
 #include "base/strings/stringprintf.h"
 #include "content/public/browser/notification_service.h"
 #include "content/public/browser/notification_types.h"
 #include "content/public/browser/render_widget_host_view.h"
 #include "content/public/browser/web_contents.h"
 
 using content::NavigationController;
 using content::RenderWidgetHost;
 using content::WebContents;
 
+namespace {
+
+// Metric names.
+const char kSessionRestoreActions[] = "SessionRestore.Actions";
+const char kSessionRestoreTabCount[] = "SessionRestore.TabCount";
+const char kSessionRestoreTabActions[] = "SessionRestore.TabActions";
+
+// The enumeration values stored in the kSessionRestoreActions histogram.
+enum SessionRestoreActionsUma {
+  // Counts the total number of session restores that have occurred.
+  SESSION_RESTORE_ACTIONS_UMA_INITIATED = 0,
+  // Counts the number of session restores that have been deferred tab loadings
+  // for whatever reason (almost certainly due to memory pressure).
+  SESSION_RESTORE_ACTIONS_UMA_DEFERRED_TABS = 1,
+  // The size of this enum. Must be the last entry.
+  SESSION_RESTORE_ACTIONS_UMA_MAX,
+};
+
+// The enumeration of values stored in the kSessionRestoreTabActions histogram.
+enum SessionRestoreTabActionsUma {
+  // Incremented for each tab created in a session restore.
+  SESSION_RESTORE_TAB_ACTIONS_UMA_TAB_CREATED = 0,
+  // Incremented for each tab that session restore decides not to load.
+  SESSION_RESTORE_TAB_ACTIONS_UMA_TAB_LOADING_DEFERRED = 1,
+  // Incremented for each tab that is successfully loaded.
+  SESSION_RESTORE_TAB_ACTIONS_UMA_TAB_LOADED = 2,
+  // Incremented for each session-restore-deferred tab that is subsequently
+  // loaded.
+  SESSION_RESTORE_TAB_ACTIONS_UMA_DEFERRED_TAB_LOADED = 3,
+  // The size of this enum. Must be the last entry.
+  SESSION_RESTORE_TAB_ACTIONS_UMA_MAX,
+};
+
+}  // namespace
+
 // static
 void SessionRestoreStatsCollector::TrackTabs(
     const std::vector<SessionRestoreDelegate::RestoredTab>& tabs,
     const base::TimeTicks& restore_started) {
   if (!shared_collector_)
     shared_collector_ = new SessionRestoreStatsCollector(restore_started);
 
   shared_collector_->AddTabs(tabs);
 }
 
 // static
-void SessionRestoreStatsCollector::TrackActiveTabs(
-    const std::vector<SessionRestoreDelegate::RestoredTab>& tabs,
-    const base::TimeTicks& restore_started) {
-  if (!shared_collector_)
-    shared_collector_ = new SessionRestoreStatsCollector(restore_started);
-
-  std::vector<SessionRestoreDelegate::RestoredTab> active_tabs;
-  for (auto tab : tabs) {
-    if (tab.is_active())
-      active_tabs.push_back(tab);
-  }
-  shared_collector_->AddTabs(active_tabs);
+void SessionRestoreStatsCollector::DeferTab(
+    content::NavigationController* tab) {
+  // It only makes sense for this to have been called *after* TrackTabs, so a
+  // stats collector will always exist.
+  DCHECK(shared_collector_);
+  shared_collector_->DeferTabImpl(tab);
 }
 
 SessionRestoreStatsCollector::SessionRestoreStatsCollector(
     const base::TimeTicks& restore_started)
     : got_first_foreground_load_(false),
       got_first_paint_(false),
       restore_started_(restore_started),
-      tab_count_(0),
-      max_parallel_tab_loads_(0) {
+      render_widget_hosts_loading_deferred_count_(0u),
+      tabs_tracked_deferred_count_(0u),
+      tab_count_(0u),
+      tab_deferred_count_(0u),
+      max_parallel_tab_loads_(0u) {
   this_retainer_ = this;
   registrar_.Add(
       this, content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
       content::NotificationService::AllSources());
 }
 
 SessionRestoreStatsCollector::~SessionRestoreStatsCollector() {
-  DCHECK((got_first_paint_ || render_widget_hosts_to_paint_.empty()) &&
-         tabs_tracked_.empty() && render_widget_hosts_loading_.empty());
-  DCHECK(shared_collector_ == this);
-  shared_collector_ = nullptr;
+  // The collector should only be destroyed when tracking is entirely
+  // finished. It should already have beend detached from being the shared
+  // collector.
+  DCHECK(shared_collector_ != this);
+  DCHECK(DoneTracking());
 }
 
 void SessionRestoreStatsCollector::Observe(
     int type,
     const content::NotificationSource& source,
     const content::NotificationDetails& details) {
   switch (type) {
     case content::NOTIFICATION_LOAD_START: {
-      // Add this render_widget_host to the set of those we're waiting for
-      // paints on. We want to only record stats for paints that occur after
-      // a load has finished.
       NavigationController* tab =
           content::Source<NavigationController>(source).ptr();
+      bool is_deferred = IsDeferred(tab);
+
+      // Add this render_widget_host to the set of those that are loading.
       RenderWidgetHost* render_widget_host = GetRenderWidgetHost(tab);
       DCHECK(render_widget_host);
-      render_widget_hosts_loading_.insert(render_widget_host);
+      render_widget_hosts_loading_.insert(
+          std::make_pair(render_widget_host, is_deferred));
+      if (is_deferred)
+        ++render_widget_hosts_loading_deferred_count_;
+
       break;
     }
     case content::NOTIFICATION_WEB_CONTENTS_DESTROYED: {
       WebContents* web_contents = content::Source<WebContents>(source).ptr();
-      RemoveTab(&web_contents->GetController());
+      NavigationController* tab = &web_contents->GetController();
+      RemoveTab(tab);
       break;
     }
     case content::NOTIFICATION_LOAD_STOP: {
+      // Remove the tab from the tracking maps.
       NavigationController* tab =
           content::Source<NavigationController>(source).ptr();
       RenderWidgetHost* render_widget_host = GetRenderWidgetHost(tab);
-      render_widget_hosts_to_paint_.insert(render_widget_host);
+      auto tab_it = tabs_tracked_.find(tab);
+      bool is_deferred = tab_it->second;
       RemoveTab(tab);
+
+      // If first paint hasn't yet been seen then add this tab to the set of
+      // those being tracked for first paints.
+      if (!got_first_paint_ && render_widget_host)
+        render_widget_hosts_to_paint_.insert(render_widget_host);
+
+      // Note the fact that this tab loaded.
+      auto tab_action = is_deferred ?
+          SESSION_RESTORE_TAB_ACTIONS_UMA_DEFERRED_TAB_LOADED :
+          SESSION_RESTORE_TAB_ACTIONS_UMA_TAB_LOADED;
+      UMA_HISTOGRAM_ENUMERATION(kSessionRestoreTabActions,
+                                tab_action,
+                                SESSION_RESTORE_TAB_ACTIONS_UMA_MAX);
+
+      // Update UMA stats for foreground tabs.
       if (!got_first_foreground_load_ && render_widget_host &&
           render_widget_host->GetView() &&
           render_widget_host->GetView()->IsShowing()) {
         got_first_foreground_load_ = true;
         base::TimeDelta time_to_load =
             base::TimeTicks::Now() - restore_started_;
         UMA_HISTOGRAM_CUSTOM_TIMES("SessionRestore.ForegroundTabFirstLoaded",
                                    time_to_load,
                                    base::TimeDelta::FromMilliseconds(10),
                                    base::TimeDelta::FromSeconds(100), 100);
         // Record a time for the number of tabs, to help track down
         // contention.
         std::string time_for_count = base::StringPrintf(
             "SessionRestore.ForegroundTabFirstLoaded_%d", tab_count_);
         base::HistogramBase* counter_for_count =
             base::Histogram::FactoryTimeGet(
                 time_for_count, base::TimeDelta::FromMilliseconds(10),
                 base::TimeDelta::FromSeconds(100), 100,
                 base::Histogram::kUmaTargetedHistogramFlag);
         counter_for_count->AddTime(time_to_load);
       }
       break;
     }
     case content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE: {
+      // This notification is across all tabs in the browser so notifications
+      // will arrive for tabs that the collector is not explicitly tracking.
+
+      // Only process this event if first paint hasn't been seen and this is a
+      // paint of a visible tab.
       RenderWidgetHost* render_widget_host =
           content::Source<RenderWidgetHost>(source).ptr();
-      if (!got_first_paint_ && render_widget_host->GetView() &&
+      if (!got_first_paint_ &&
+          render_widget_host->GetView() &&
           render_widget_host->GetView()->IsShowing()) {
-        if (render_widget_hosts_to_paint_.find(render_widget_host) !=
-            render_widget_hosts_to_paint_.end()) {
+        // If this is a paint for a tab that is explicitly being tracked for
+        // paint events then record the appropriate UMA statistic.
+        auto render_widget_host_it =
+            render_widget_hosts_to_paint_.find(render_widget_host);
+        if (render_widget_host_it != render_widget_hosts_to_paint_.end()) {
+          // Stop tracking this tab.
+          render_widget_hosts_to_paint_.erase(render_widget_host_it);
+
           // Got a paint for one of our renderers, so record time.
           got_first_paint_ = true;
           base::TimeDelta time_to_paint =
               base::TimeTicks::Now() - restore_started_;
           // TODO(danduong): to remove this with 467680, to make sure we
           // don't forget to clean this up.
           UMA_HISTOGRAM_CUSTOM_TIMES("SessionRestore.ForegroundTabFirstPaint",
                                      time_to_paint,
                                      base::TimeDelta::FromMilliseconds(10),
                                      base::TimeDelta::FromSeconds(100), 100);
           // Record a time for the number of tabs, to help track down
           // contention.
           std::string time_for_count = base::StringPrintf(
               "SessionRestore.ForegroundTabFirstPaint_%d", tab_count_);
           base::HistogramBase* counter_for_count =
               base::Histogram::FactoryTimeGet(
                   time_for_count, base::TimeDelta::FromMilliseconds(10),
                   base::TimeDelta::FromSeconds(100), 100,
                   base::Histogram::kUmaTargetedHistogramFlag);
           counter_for_count->AddTime(time_to_paint);
-          UMA_HISTOGRAM_CUSTOM_TIMES("SessionRestore.ForegroundTabFirstPaint2",
-                                     time_to_paint,
-                                     base::TimeDelta::FromMilliseconds(100),
-                                     base::TimeDelta::FromMinutes(16), 50);
+          UMA_HISTOGRAM_CUSTOM_TIMES(
+              "SessionRestore.ForegroundTabFirstPaint2",
+              time_to_paint,
+              base::TimeDelta::FromMilliseconds(100),
+              base::TimeDelta::FromMinutes(16), 50);
           // Record a time for the number of tabs, to help track down
           // contention.
           std::string time_for_count2 = base::StringPrintf(
               "SessionRestore.ForegroundTabFirstPaint2_%d", tab_count_);
           base::HistogramBase* counter_for_count2 =
               base::Histogram::FactoryTimeGet(
                   time_for_count2, base::TimeDelta::FromMilliseconds(100),
                   base::TimeDelta::FromMinutes(16), 50,
                   base::Histogram::kUmaTargetedHistogramFlag);
           counter_for_count2->AddTime(time_to_paint);
         } else if (render_widget_hosts_loading_.find(render_widget_host) ==
                    render_widget_hosts_loading_.end()) {
-          // If this is a host for a tab we're not loading some other tab
+          // If this is a host for a tab we're not tracking then some other tab
           // has rendered and there's no point tracking the time. This could
           // happen because the user opened a different tab or restored tabs
           // to an already existing browser and an existing tab painted.
           got_first_paint_ = true;
         }
+
+        if (got_first_paint_) {
+          // If the first paint has been observed the entire to-paint tracking
+          // mechanism is no longer needed.
+          registrar_.Remove(
+              this,
+              content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
+              content::NotificationService::AllSources());
+          render_widget_hosts_to_paint_.clear();
+        }
       }
       break;
     }
     default:
       NOTREACHED() << "Unknown notification received:" << type;
       break;
   }
 
-  // Check if we are done and if so, reset |this_retainer_| as the collector no
-  // longer needs to stay alive.
-  if ((got_first_paint_ || render_widget_hosts_to_paint_.empty()) &&
-      tabs_tracked_.empty() && render_widget_hosts_loading_.empty())
+  // If non-deferred tabs are no longer being tracked then detach this collector
+  // from being the shared collector. This allows new session restores to get
+  // new stats collectors. It also means that multiple stats collectors can
+  // exist simultaneously.
+  if (shared_collector_ == this && DoneTrackingNonDeferredTabs())
+    shared_collector_ = nullptr;
+
+  // If tracking is completely finished destroy this stats collector.
+  if (shared_collector_ != this && DoneTracking())
     this_retainer_ = nullptr;
 }
 
 void SessionRestoreStatsCollector::AddTabs(
     const std::vector<SessionRestoreDelegate::RestoredTab>& tabs) {
+  // A new session restore is starting.
+  if (tab_count_ == 0) {
+    // Each session restore makes a call to AddTabs with all of its tabs to be
+    // restored all at once. Record statistics about all simultaneous session
+    // restores (ie: multi-profile) as a whole.
+    UMA_HISTOGRAM_COUNTS_100(kSessionRestoreTabCount, tabs.size());
+    UMA_HISTOGRAM_ENUMERATION(kSessionRestoreActions,
+                              SESSION_RESTORE_ACTIONS_UMA_INITIATED,
+                              SESSION_RESTORE_ACTIONS_UMA_MAX);
+  }
+
   tab_count_ += tabs.size();
   for (auto& tab : tabs) {
+    // Record actions for each individual tab.
+    UMA_HISTOGRAM_ENUMERATION(kSessionRestoreTabActions,
+                              SESSION_RESTORE_TAB_ACTIONS_UMA_TAB_CREATED,
+                              SESSION_RESTORE_TAB_ACTIONS_UMA_MAX);
+
     RegisterForNotifications(&tab.contents()->GetController());
     if (tab.is_active()) {
       RenderWidgetHost* render_widget_host =
           GetRenderWidgetHost(&tab.contents()->GetController());
-      render_widget_hosts_loading_.insert(render_widget_host);
+      render_widget_hosts_loading_.insert(
+          std::make_pair(render_widget_host, false));
     }
   }
 }
 
+void SessionRestoreStatsCollector::DeferTabImpl(
+    content::NavigationController* tab) {
+  auto tab_it = tabs_tracked_.find(tab);
+  // If the tab is no longer being tracked it has already started loading,
+  // likely due to user action. Ignore the call to defer the tab.
+  // TODO(chrisha): Is it worth explicitly tracking these events as well?

[chrisha, 2015/05/13 21:18:02]

Consider this a question... your thoughts?

+  if (tab_it == tabs_tracked_.end())
+    return;
+
+  // Mark this tab as deferred, if its still being tracked. A tab should not be
+  // marked as deferred twice.
+  DCHECK(!tab_it->second);
+  tab_it->second = true;
+  ++tabs_tracked_deferred_count_;
+  ++tab_deferred_count_;
+
+  // It is possible that the tab is loading so also look in the loading render
+  // widget host map in this case.
+  auto render_widget_host = GetRenderWidgetHost(tab);
+  auto render_widget_host_it = render_widget_hosts_loading_.find(
+      render_widget_host);
+  if (render_widget_host_it != render_widget_hosts_loading_.end()) {
+    DCHECK(!render_widget_host_it->second);
+    render_widget_host_it->second = true;
+    ++render_widget_hosts_loading_deferred_count_;
+  }
+
+  // If this is the first tab being deferred indicate that the session has had
+  // deferred tabs.
+  if (tab_deferred_count_ == 1) {
+    // It is assumed that tabs are being deferred due to memory pressure as this
+    // is currently the only mechanism in which this can happen.
+    UMA_HISTOGRAM_ENUMERATION(kSessionRestoreActions,
+                              SESSION_RESTORE_ACTIONS_UMA_DEFERRED_TABS,
+                              SESSION_RESTORE_ACTIONS_UMA_MAX);
+  }
+
+  UMA_HISTOGRAM_ENUMERATION(
+      kSessionRestoreTabActions,
+      SESSION_RESTORE_TAB_ACTIONS_UMA_TAB_LOADING_DEFERRED,
+      SESSION_RESTORE_TAB_ACTIONS_UMA_MAX);
+}
+
 void SessionRestoreStatsCollector::RemoveTab(NavigationController* tab) {
+  // Stop observing this tab.
   registrar_.Remove(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
                     content::Source<WebContents>(tab->GetWebContents()));
   registrar_.Remove(this, content::NOTIFICATION_LOAD_STOP,
                     content::Source<NavigationController>(tab));
   registrar_.Remove(this, content::NOTIFICATION_LOAD_START,
                     content::Source<NavigationController>(tab));
+
+  // Remove the tab from the tracked_tabs map and be sure to update the count
+  // of deferred tracked tabs if necessary.
+  auto tab_it = tabs_tracked_.find(tab);
+  bool is_deferred = tab_it->second;
+  tabs_tracked_.erase(tab_it);
+  if (is_deferred)
+    --tabs_tracked_deferred_count_;
+
+  // Keep track of the maximum number of tabs that are loading at the same time.
+  // NOTE: This counts session restore loaded tabs and *user* loaded tabs,
+  //       both deferred and otherwise. This preserves the original behaviour of
+  //       this metric.
   if (render_widget_hosts_loading_.size() > max_parallel_tab_loads_)
     max_parallel_tab_loads_ = render_widget_hosts_loading_.size();
+
+  // Remove the tab from the loading render widget host map. If the tab is
+  // present in this map and deferred, then also update the deferred count.
   RenderWidgetHost* render_widget_host = GetRenderWidgetHost(tab);
-  render_widget_hosts_loading_.erase(render_widget_host);
-  tabs_tracked_.erase(tab);
+  if (is_deferred && render_widget_hosts_loading_.erase(render_widget_host))
+    --render_widget_hosts_loading_deferred_count_;
 
-  // If there are no more tabs loading or being tracked, restore is done and
-  // record the time. Note that we are not yet finished, as we might still be
-  // waiting for our first paint, which can happen after all tabs are done
-  // loading.
-  // TODO(georgesak): review behaviour of ForegroundTabFirstPaint.
-  if (tabs_tracked_.empty() && render_widget_hosts_loading_.empty()) {
+  // Calculate the number of non-deferred tracked and loading tabs. These are
+  // used to determine whether session restore has completed tab loading.
+  size_t tracked = tabs_tracked_.size() - tabs_tracked_deferred_count_;
+  size_t loading = render_widget_hosts_loading_.size() -
+      render_widget_hosts_loading_deferred_count_;
+
+  // If there are no more non-deferred tabs loading or being tracked, the active
+  // portion of restore is done so record the time. Note that stats collection
+  // is not yet finished, as there can be deferred tabs and pending paint
+  // events.
+  // NOTE: This is only concerned with tabs that are being actively tracked,
+  //       and not deferred tabs. Deferred tabs are still tracked, but don't
+  //       affect the AllTabsLoaded metric.
+  // TODO(georgesak): Review behaviour of ForegroundTabFirstPaint.
+  if (tracked == 0 && loading == 0) {
     base::TimeDelta time_to_load = base::TimeTicks::Now() - restore_started_;
     UMA_HISTOGRAM_CUSTOM_TIMES("SessionRestore.AllTabsLoaded", time_to_load,
                                base::TimeDelta::FromMilliseconds(10),
                                base::TimeDelta::FromSeconds(100), 100);
     // Record a time for the number of tabs, to help track down contention.
     std::string time_for_count =
         base::StringPrintf("SessionRestore.AllTabsLoaded_%d", tab_count_);
     base::HistogramBase* counter_for_count = base::Histogram::FactoryTimeGet(
         time_for_count, base::TimeDelta::FromMilliseconds(10),
         base::TimeDelta::FromSeconds(100), 100,
         base::Histogram::kUmaTargetedHistogramFlag);
     counter_for_count->AddTime(time_to_load);
 
     UMA_HISTOGRAM_COUNTS_100("SessionRestore.ParallelTabLoads",
                              max_parallel_tab_loads_);
   }
 }
 
 void SessionRestoreStatsCollector::RegisterForNotifications(
     NavigationController* tab) {
   registrar_.Add(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
                  content::Source<WebContents>(tab->GetWebContents()));
   registrar_.Add(this, content::NOTIFICATION_LOAD_STOP,
                  content::Source<NavigationController>(tab));
   registrar_.Add(this, content::NOTIFICATION_LOAD_START,
                  content::Source<NavigationController>(tab));
-  tabs_tracked_.insert(tab);
+  // All tabs are non-deferred to start with.
+  tabs_tracked_.insert(std::make_pair(tab, false));
 }
 
 RenderWidgetHost* SessionRestoreStatsCollector::GetRenderWidgetHost(
     NavigationController* tab) {
   WebContents* web_contents = tab->GetWebContents();
   if (web_contents) {
     content::RenderWidgetHostView* render_widget_host_view =
         web_contents->GetRenderWidgetHostView();
     if (render_widget_host_view)
       return render_widget_host_view->GetRenderWidgetHost();
   }
   return nullptr;
 }
 
+bool SessionRestoreStatsCollector::IsDeferred(
+    content::NavigationController* tab) const {
+  auto tab_it = tabs_tracked_.find(tab);
+  DCHECK(tab_it != tabs_tracked_.end());
+  return tab_it->second;
+}
+
+bool SessionRestoreStatsCollector::DoneTrackingNonDeferredTabs() const {
+  // If first paint hasn't been seen and tabs are being tracked for paints
+  // (ie: a first paint could yet be seen) then the stats collector is not done.
+  if (!got_first_paint_ && !render_widget_hosts_to_paint_.empty())
+    return false;
+
+  // No non-deferred tabs should be in the tracked map.
+  size_t tracked = tabs_tracked_.size() - tabs_tracked_deferred_count_;
+  if (tracked > 0)
+    return false;
+
+  // No non-deferred tabs should be in the loading map.
+  size_t loading = render_widget_hosts_loading_.size() -
+      render_widget_hosts_loading_deferred_count_;
+  if (loading > 0)
+    return false;
+
+  return true;
+}
+
+bool SessionRestoreStatsCollector::DoneTracking() const {
+  // This should only be called once all non-deferred tabs have finished
+  // tracking.
+  DCHECK(DoneTrackingNonDeferredTabs());
+  return render_widget_hosts_loading_.empty() && tabs_tracked_.empty();
+}
+
 // static
 SessionRestoreStatsCollector* SessionRestoreStatsCollector::shared_collector_ =
     nullptr;