[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.
+  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,
     const base::TimeTicks& restore_started) {
   if (!shared_collector_)
     shared_collector_ = new SessionRestoreStatsCollector(restore_started);
 
   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(
       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;
 }
 
 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);
+
+      // 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);
       break;
     }
     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()) {
         got_first_foreground_load_ = true;
         base::TimeDelta time_to_load =
             base::TimeTicks::Now() - restore_started_;
         UMA_HISTOGRAM_CUSTOM_TIMES("SessionRestore.ForegroundTabFirstLoaded",

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

Seems like we should never log this if any tab was deferred.

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

I'm not sure I agree... there will always be at least one tab loaded (there will
be at least one visible tab), so why wouldn't we emit this?

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

Two cases to consider:
. what happens when you close tabs that are loading before they stop?
. what happens if the network is unavailable?

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

These are concerns regardless of whether or not there are deferred tabs. The
stats collector doesn't do anything different now than it did for deferred tabs.
If we didn't change the stats collector to understand them and emit a few more
events, a deferred tab is indistinguishable from a tab that was loaded by the
tab loader arbitrarily far after the session restore initiated.

So if you want to address these specific issues, let's deal with them
separately.

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

Fair enough. As long as they get dealt with.

[chrisha, 2015/05/26 20:00:18]

Added a TODO capturing this.

                                    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),
@@ skipping 62 matching lines @@
 
   // 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())
     this_retainer_ = nullptr;
 }
 
 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 =
           GetRenderWidgetHost(&tab.contents()->GetController());
       render_widget_hosts_loading_.insert(render_widget_host);
     }
   }
 }
 
-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,
         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) {

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

can you make this take session_restore_id_ so that it's clearer the callsite
should be supplying the id. This way if someone wants to call
RegisterForNotifications() at some random later date they have to think about
what the id is.

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

After hashing this out with Georges, we really don't need the whole session
restore ID. I'm now philosophically on board with the whole "multiple session
restores happening at once is seen as a single session restore event". 

However, the deferred tabs now create a longer lifespan for the stats collector,
which could cause it to start collecting stats again for subsequent session
restores that *aren't* coincident with the first ones. To deal with this I've
moved to a 2 stage end-of-life management:

1. When only deferred tabs remain to be tracked, the stats collector detaches
itself from the shared_collector_. This allows a new collector to be created for
new session restores.
2. When no tabs at all remain to be tracked, the collector deletes itself as
before.

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

I have to think about that more. I'm concerned that if the two don't start close
enough some of these metrics are going to be misleading.

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

This is effectively preserving the existing behavior. A stats collector will now
detach from being the shared collector at the same time as before (all tabs
loaded, first paint seen), and actually even *sooner* if some tabs are deferred.
Thus, the window of time when multiple session restores collapse to one can only
actually get smaller compared to the previous situation.

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

I think the old behavior is wrong in some cases. I'm fine for addressing
separately.

[chrisha, 2015/05/26 20:00:18]

Added a TODO capturing this.

   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);
+  tabs_tracked_.insert(std::make_pair(tab, session_restore_id_));
 }
 
 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) {
+  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;