[Sessions] Add detailed logging of SessionRestore events.

chrome/browser/sessions/session_restore_stats_collector.cc

Index: chrome/browser/sessions/session_restore_stats_collector.cc
diff --git a/chrome/browser/sessions/session_restore_stats_collector.cc b/chrome/browser/sessions/session_restore_stats_collector.cc
index f593b6eb299186711d4b4546b118c676c3f6413b..c1299b2a245a6d28e75241e56ccb8b1fd6133c0b 100644
--- a/chrome/browser/sessions/session_restore_stats_collector.cc
+++ b/chrome/browser/sessions/session_restore_stats_collector.cc
@@ -17,6 +17,51 @@ 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.
+  kSessionRestoreActionsUma_Initiated = 0,

[sky, 2015/05/12 15:27:56]

SESSION_RESTORE_ACTION_UMA_INITIATED (see chrome style guide).

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

Done.

+  // Counts the number of session restores that have been deferred tab loadings
+  // for whatever reason (almost certainly due to memory pressure).
+  kSessionRestoreActionsUma_DeferredTabs = 1,
+  // The size of this enum. Must be the last entry.
+  kSessionRestoreActionsUma_Max,
+};
+
+// The enumeration of values stored in the kSessionRestoreTabActions histogram.
+enum SessionRestoreTabActionsUma {
+  // Incremented for each tab created in a session restore.
+  kSessionRestoreTabActionsUma_TabCreated = 0,
+  // Incremented for each tab started to load by the session restore.
+  kSessionRestoreTabActionsUma_TabLoading = 1,
+  // Incremented for each tab that session restore decides not to load.
+  kSessionRestoreTabActionsUma_TabLoadingDeferred = 2,
+  // Incremented for each tab that is successfully loaded.
+  kSessionRestoreTabActionsUma_TabLoaded = 3,
+  // Incremented for each session-restore-deferred tab that subsequently starts
+  // to load.
+  kSessionRestoreTabActionsUma_DeferredTabLoading = 4,
+  // Incremented for each non-deferred not-yet-loaded tab closed by the user.
+  kSessionRestoreTabActionsUma_NonDeferredNotLoadingTabClosed = 5,
+  // Incremented for each non-deferred actively-loading tab closed by the user.
+  kSessionRestoreTabActionsUma_NonDeferredLoadingTabClosed = 6,
+  // Incremented for each deferred not-yet-loaded tab closed by the user.
+  kSessionRestoreTabActionsUma_DeferredNotLoadingTabClosed = 7,
+  // Incremented for each deferred actively-loading tab closed by the user.
+  kSessionRestoreTabActionsUma_DeferredLoadingTabClosed = 8,
+  // The size of this enum. Must be the last entry.
+  kSessionRestoreTabActionsUma_Max,
+};
+
+}  // namespace
+
 // static
 void SessionRestoreStatsCollector::TrackTabs(
     const std::vector<SessionRestoreDelegate::RestoredTab>& tabs,
@@ -27,12 +72,22 @@ void SessionRestoreStatsCollector::TrackTabs(
   shared_collector_->AddTabs(tabs);
 }
 
+// static
+void SessionRestoreStatsCollector::DeferTab(
+    content::NavigationController* tab) {
+  // It only makes sense for this to have been called *after* DeferTab, so a
+  // stats collector will always exist.

[sky, 2015/05/12 15:27:56]

DCHECK(shared_collector_)

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

Done.

+  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),
+      tab_deferred_count_(0),
+      session_restore_id_(0),
       max_parallel_tab_loads_(0) {
   this_retainer_ = this;
   registrar_.Add(
@@ -58,6 +113,16 @@ void SessionRestoreStatsCollector::Observe(
       // a load has finished.
       NavigationController* tab =
           content::Source<NavigationController>(source).ptr();
+      bool is_deferred = IsDeferred(tab);
+
+      // Record the appropriate tab loading event type.
+      auto tab_action =
+          is_deferred ? kSessionRestoreTabActionsUma_TabLoading :
+                        kSessionRestoreTabActionsUma_DeferredTabLoading;
+      UMA_HISTOGRAM_ENUMERATION(kSessionRestoreTabActions,
+                                tab_action,
+                                kSessionRestoreTabActionsUma_Max);
+
       RenderWidgetHost* render_widget_host = GetRenderWidgetHost(tab);
       DCHECK(render_widget_host);
       render_widget_hosts_loading_.insert(render_widget_host);
@@ -65,15 +130,46 @@ void SessionRestoreStatsCollector::Observe(
     }
     case content::NOTIFICATION_WEB_CONTENTS_DESTROYED: {
       WebContents* web_contents = content::Source<WebContents>(source).ptr();
-      RemoveTab(&web_contents->GetController());
+      NavigationController* tab = &web_contents->GetController();
+      bool is_deferred = IsDeferred(tab);
+
+      // Record a tab action for the tab that is being closed. If this tab is
+      // loading it will have a RenderWidgetHost in the tracking set.
+      RenderWidgetHost* render_widget_host = GetRenderWidgetHost(tab);
+      auto tab_action = kSessionRestoreTabActionsUma_Max;
+      if (render_widget_hosts_loading_.count(render_widget_host) > 0) {
+        // This tab is loading.
+        tab_action = is_deferred ?
+            kSessionRestoreTabActionsUma_DeferredLoadingTabClosed :
+            kSessionRestoreTabActionsUma_NonDeferredLoadingTabClosed;
+      } else {
+        // This tab is not loading.
+        tab_action = is_deferred ?
+            kSessionRestoreTabActionsUma_DeferredNotLoadingTabClosed :
+            kSessionRestoreTabActionsUma_NonDeferredNotLoadingTabClosed;
+      }
+      UMA_HISTOGRAM_ENUMERATION(kSessionRestoreTabActions,
+                                tab_action,
+                                kSessionRestoreTabActionsUma_Max);
+
+      RemoveTab(is_deferred, tab);
       break;
     }
     case content::NOTIFICATION_LOAD_STOP: {
       NavigationController* tab =
           content::Source<NavigationController>(source).ptr();
+      bool is_deferred = IsDeferred(tab);
       RenderWidgetHost* render_widget_host = GetRenderWidgetHost(tab);
       render_widget_hosts_to_paint_.insert(render_widget_host);
-      RemoveTab(tab);
+
+      // Note the fact that this tab loaded.
+      UMA_HISTOGRAM_ENUMERATION(kSessionRestoreTabActions,
+                                kSessionRestoreTabActionsUma_TabLoaded,
+                                kSessionRestoreTabActionsUma_Max);
+
+      RemoveTab(is_deferred, tab);
+
+      // Update UMA stats for foreground tabs.
       if (!got_first_foreground_load_ && render_widget_host &&
           render_widget_host->GetView() &&
           render_widget_host->GetView()->IsShowing()) {
@@ -163,8 +259,25 @@ void SessionRestoreStatsCollector::Observe(
 
 void SessionRestoreStatsCollector::AddTabs(
     const std::vector<SessionRestoreDelegate::RestoredTab>& tabs) {
+  // Increment the session restore ID so to distinguish which tabs belong to
+  // which conceptual session restore.
+  ++session_restore_id_;
+
+  // Each session restore makes a call to AddTabs with all of its tabs to be
+  // restored all at once. Record statistics about the session restore as a
+  // whole.
+  UMA_HISTOGRAM_COUNTS_100(kSessionRestoreTabCount, tabs.size());
+  UMA_HISTOGRAM_ENUMERATION(kSessionRestoreActions,
+                            kSessionRestoreActionsUma_Initiated,
+                            kSessionRestoreActionsUma_Max);
+
   tab_count_ += tabs.size();
   for (auto& tab : tabs) {
+    // Record actions for each individual tab.
+    UMA_HISTOGRAM_ENUMERATION(kSessionRestoreTabActions,
+                              kSessionRestoreTabActionsUma_TabCreated,
+                              kSessionRestoreTabActionsUma_Max);
+
     RegisterForNotifications(&tab.contents()->GetController());
     if (tab.is_active()) {
       RenderWidgetHost* render_widget_host =
@@ -174,32 +287,74 @@ void SessionRestoreStatsCollector::AddTabs(
   }
 }
 
-void SessionRestoreStatsCollector::RemoveTab(NavigationController* tab) {
+void SessionRestoreStatsCollector::DeferTabImpl(
+    content::NavigationController* tab) {
+  // We simply move this tab from the tracked set to the deferred set.
+  ++tab_deferred_count_;
+  auto tracked_it = tabs_tracked_.find(tab);
+  int session_id = tracked_it->second;
+  tabs_deferred_.insert(*tracked_it);
+  tabs_tracked_.erase(tracked_it);
+
+  // Only indicate that the session has had deferred tabs if this is the first
+  // tab associated with that session being deferred.
+  if (deferred_tabs_seen_.insert(session_id).second) {
+    // 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,
+                              kSessionRestoreActionsUma_DeferredTabs,
+                              kSessionRestoreActionsUma_Max);
+  }
+
+  UMA_HISTOGRAM_ENUMERATION(kSessionRestoreTabActions,
+                            kSessionRestoreTabActionsUma_TabLoadingDeferred,
+                            kSessionRestoreTabActionsUma_Max);
+}
+
+void SessionRestoreStatsCollector::RemoveTab(bool is_deferred,
+                                             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));
-  if (render_widget_hosts_loading_.size() > max_parallel_tab_loads_)
+
+  // Keep track of the maximum number of automatically loaded tabs that are
+  // loading at the same time.
+  if (!is_deferred &&
+      render_widget_hosts_loading_.size() > max_parallel_tab_loads_) {
     max_parallel_tab_loads_ = render_widget_hosts_loading_.size();
+  }
+
   RenderWidgetHost* render_widget_host = GetRenderWidgetHost(tab);
   render_widget_hosts_loading_.erase(render_widget_host);
-  tabs_tracked_.erase(tab);
+
+  // Remove the tab from the appropriate list.
+  if (is_deferred) {
+    tabs_deferred_.erase(tab);
+  } else {
+    tabs_tracked_.erase(tab);
+  }
 

[sky, 2015/05/12 15:27:56]

Would be nice to have some DCHECKs here that tab is in the right list.

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

I moved to using a map that tracks the 'deferred' state. Made the logic much
easier pretty much everywhere.

   // 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.
+  // 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 (tabs_tracked_.empty() && render_widget_hosts_loading_.empty()) {

[sky, 2015/05/12 15:27:56]

Lets say tabs_tracked_ goes empty, adoesn't that mean you're going to hit this
code n more times where n is the number of deferred tabs?

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

Yes, that's true. This is no worse than before in that it will be hit once for
each tab involved in the session restore. Deferred tabs are a subset of those.

This is also made a little clearer by moving to a single tabs_tracked_ map.

[sky, 2015/05/14 00:12:40]

Not sure there. I think you're change makes it worse, but that's separate. We
should only report this once.
Yes, I think that will help.

[chrisha, 2015/05/14 21:27:02]

The 'deferred state' of a tab doesn't change it's lifetime, nor its flow through
the various maps/sets that the stats collector tracks. At its heart, a tab goes
through a few simple states:

- not loading
- loading
- loaded
- painted (if we bother to track this)

RemoveTab can only be called on a tab at most once, so no more processing is
done here. The number of tabs entering the stats collector via TrackTabs remains
unchanged, so no extra work is done there. Calls to DeferTab only modify the
state of a tab that is already being tracked. This represents a minor amount of
extra work, O(1) per deferred tab, to a max of O(n). The deferred state is only
used to change the exact type of UMA records emitted, and to decide when to
detach from being the shared collector.

The *lifetime* of the shared collector is significantly longer, and this has
memory overhead, but no more entries into the stats collector in the worst case
than already exist.

Since the lifetime is much longer many more useless UPDATE_BACKING_STORE calls
could be seen. However, to deal with this I've disabled these callbacks as soon
as first paint has been observed. By the time the stats collector is detached
from being the shared collector, it will be receiving no more of these events.

[sky, 2015/05/14 21:51:50]

Ok.

     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.
+    int tabs_loaded = tab_count_ - tab_deferred_count_;
     std::string time_for_count =
-        base::StringPrintf("SessionRestore.AllTabsLoaded_%d", tab_count_);
+        base::StringPrintf("SessionRestore.AllTabsLoaded_%d", tabs_loaded);
     base::HistogramBase* counter_for_count = base::Histogram::FactoryTimeGet(
         time_for_count, base::TimeDelta::FromMilliseconds(10),
         base::TimeDelta::FromSeconds(100), 100,
@@ -219,7 +374,7 @@ void SessionRestoreStatsCollector::RegisterForNotifications(
                  content::Source<NavigationController>(tab));
   registrar_.Add(this, content::NOTIFICATION_LOAD_START,
                  content::Source<NavigationController>(tab));
-  tabs_tracked_.insert(tab);
+  tabs_tracked_.insert(std::make_pair(tab, session_restore_id_));
 }
 
 RenderWidgetHost* SessionRestoreStatsCollector::GetRenderWidgetHost(
@@ -234,6 +389,13 @@ RenderWidgetHost* SessionRestoreStatsCollector::GetRenderWidgetHost(
   return nullptr;
 }
 
+bool SessionRestoreStatsCollector::IsDeferred(
+    content::NavigationController* tab) {
+  if (tabs_deferred_.count(tab) > 0)

[sky, 2015/05/12 15:27:56]

nit: return tabs_deffered_.count(tab) > 0

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

(I have a tendency to write code this way because it means I can easily put a
breakpoint on either of the two conditions. Philosophical argument, but in this
particular case I don't care either way.)

Done.

+    return true;
+  return false;
+}
+
 // static
 SessionRestoreStatsCollector* SessionRestoreStatsCollector::shared_collector_ =
     nullptr;