[Sessions] Add detailed logging of SessionRestore events.

chrome/browser/sessions/session_restore_stats_collector_unittest.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 "base/message_loop/message_loop.h"
+#include "base/test/simple_test_tick_clock.h"
+#include "chrome/test/base/testing_profile.h"
+#include "content/public/browser/notification_service.h"
+#include "content/public/browser/notification_types.h"
+#include "content/public/browser/render_widget_host.h"
+#include "content/public/browser/render_widget_host_view.h"
+#include "content/public/browser/web_contents.h"
+#include "content/public/test/test_browser_thread.h"
+#include "content/public/test/test_web_contents_factory.h"
+#include "testing/gmock/include/gmock/gmock.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace {
+
+using testing::_;
+using testing::AllOf;
+using testing::Eq;
+using testing::Field;
+using testing::Gt;
+using TabLoaderStats = SessionRestoreStatsCollector::TabLoaderStats;
+using StatsReportingDelegate =
+    SessionRestoreStatsCollector::StatsReportingDelegate;
+
+// A mock StatsReportingDelegate. This is used by the unittests to validate the
+// reporting and lifetime behaviour of the SessionRestoreStatsCollector under
+// test.
+class LenientMockStatsReportingDelegate : public StatsReportingDelegate {
+ public:
+  virtual ~LenientMockStatsReportingDelegate() { }
+
+  MOCK_METHOD1(ReportTabLoaderStats, void(const TabLoaderStats&));

[sky, 2015/06/17 15:33:54]

Don't use gmock. See threads in chromium-dev.

[chrisha, 2015/06/17 17:44:34]

Although I'm clearly on the other side in this holy war, done.

+  MOCK_METHOD0(ReportTabDeferred, void());
+  MOCK_METHOD0(ReportDeferredTabLoaded, void());
+
+  // This is not part of the StatsReportingDelegate, but an added function that
+  // is invoked by the PassthroughStatsReportingDelegate when it dies. This
+  // allows the tests to be notified the moment the underlying stats collector
+  // terminates itself.
+  MOCK_METHOD0(ReportStatsCollectorDeath, void());
+};
+using MockStatsReportingDelegate =
+    testing::StrictMock<LenientMockStatsReportingDelegate>;
+
+// A pass-through stats reporting delegate. This is used to decouple the
+// lifetime of the mock reporting delegate from the SessionRestoreStatsCollector
+// under test. The SessionRestoreStatsCollector has ownership of this delegate,
+// which will notify the mock delegate upon its death.
+class PassthroughStatsReportingDelegate : public StatsReportingDelegate {
+ public:
+  PassthroughStatsReportingDelegate() : reporting_delegate_(nullptr) { }
+  virtual ~PassthroughStatsReportingDelegate() {
+    reporting_delegate_->ReportStatsCollectorDeath();
+  }
+
+  void set_reporting_delegate(MockStatsReportingDelegate* reporting_delegate) {
+    reporting_delegate_ = reporting_delegate;
+  }
+
+  void ReportTabLoaderStats(const TabLoaderStats& tab_loader_stats) override {
+    reporting_delegate_->ReportTabLoaderStats(tab_loader_stats);
+  }
+
+  void ReportTabDeferred() override {
+    reporting_delegate_->ReportTabDeferred();
+  }
+
+  void ReportDeferredTabLoaded() override {
+    reporting_delegate_->ReportDeferredTabLoaded();
+  }
+
+ private:
+  MockStatsReportingDelegate* reporting_delegate_;
+};
+
+class TestSessionRestoreStatsCollector : public SessionRestoreStatsCollector {
+ public:
+  using SessionRestoreStatsCollector::Observe;
+
+  TestSessionRestoreStatsCollector(
+      scoped_ptr<base::TickClock> tick_clock,
+      scoped_ptr<StatsReportingDelegate> reporting_delegate)
+      : SessionRestoreStatsCollector(
+            tick_clock->NowTicks(),
+            reporting_delegate.Pass()) {
+    set_tick_clock(tick_clock.Pass());
+  }
+
+ private:
+  friend class base::RefCounted<TestSessionRestoreStatsCollector>;
+
+  virtual ~TestSessionRestoreStatsCollector() { }
+
+  base::SimpleTestTickClock* test_tick_clock_;
+};
+
+}  // namespace
+
+class SessionRestoreStatsCollectorTest : public testing::Test {
+ public:
+  using RestoredTab = SessionRestoreDelegate::RestoredTab;
+
+  SessionRestoreStatsCollectorTest()
+      : ui_thread_(content::BrowserThread::UI, &message_loop_) {
+  }
+
+  void SetUp() override {
+    test_web_contents_factory_.reset(
+        new content::TestWebContentsFactory);
+
+    // Ownership of the reporting delegate is passed to the
+    // SessionRestoreStatsCollector, but a raw pointer is kept to it so it can
+    // be queried by the test.
+    passthrough_reporting_delegate_ = new PassthroughStatsReportingDelegate();
+
+    // Ownership of this clock is passed to the SessionRestoreStatsCollector.
+    // A raw pointer is kept to it so that it can be modified from the outside.
+    // The unittest must take not to access the clock only while the
+    // SessionRestoreStatsCollector under test is still alive.
+    test_tick_clock_ = new base::SimpleTestTickClock();
+
+    // Create a stats collector, keep a raw pointer to it, and detach from it.
+    // The stats collector will stay alive as long as it has not yet completed
+    // its job, and will clean itself up when done.
+    scoped_refptr<TestSessionRestoreStatsCollector> stats_collector =
+        new TestSessionRestoreStatsCollector(
+            scoped_ptr<base::TickClock>(test_tick_clock_),
+            scoped_ptr<StatsReportingDelegate>(
+                passthrough_reporting_delegate_));
+    stats_collector_ = stats_collector.get();
+    stats_collector = nullptr;
+  }
+
+  void TearDown() override {
+    passthrough_reporting_delegate_ = nullptr;
+    test_tick_clock_ = nullptr;
+    stats_collector_ = nullptr;
+
+    // Clean up any tabs that were generated by the unittest.
+    restored_tabs_.clear();
+    test_web_contents_factory_.reset();
+  }
+
+  // Advances the test clock by 1ms.
+  void Tick() {
+    test_tick_clock_->Advance(base::TimeDelta::FromMilliseconds(1));
+  }
+
+  void Show(size_t tab_index) {
+    restored_tabs_[tab_index].contents()->GetRenderWidgetHostView()->Show();
+  }
+
+  void Hide(size_t tab_index) {
+    restored_tabs_[tab_index].contents()->GetRenderWidgetHostView()->Hide();
+  }
+
+  // Creates a restored tab backed by dummy WebContents/NavigationController/
+  // RenderWidgetHost/RenderWidgetHostView. Returns the index of the restored
+  // tab for future simulation of events.
+  void CreateRestoredTab(bool is_active) {
+    content::WebContents* contents =
+        test_web_contents_factory_->CreateWebContents(&testing_profile_);
+    restored_tabs_.push_back(RestoredTab(contents, is_active, false, false));
+    if (is_active)
+      Show(restored_tabs_.size() - 1);
+  }
+
+  // Helper function for various notification generation.
+  void GenerateControllerNotification(size_t tab_index, int type) {
+    content::WebContents* contents = restored_tabs_[tab_index].contents();
+    content::NavigationController* controller = &contents->GetController();
+    stats_collector_->Observe(
+        type,
+        content::Source<content::NavigationController>(controller),
+        content::NotificationService::NoDetails());
+  }
+
+  // Generates a load start notification for the given tab.
+  void GenerateLoadStart(size_t tab_index) {
+    GenerateControllerNotification(tab_index, content::NOTIFICATION_LOAD_START);
+  }
+
+  // Generates a load stop notification for the given tab.
+  void GenerateLoadStop(size_t tab_index) {
+    GenerateControllerNotification(tab_index, content::NOTIFICATION_LOAD_STOP);
+  }
+
+  // Generates a web contents destroyed notification for the given tab.
+  void GenerateWebContentsDestroyed(size_t tab_index) {
+    content::WebContents* contents = restored_tabs_[tab_index].contents();
+    stats_collector_->Observe(
+        content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
+        content::Source<content::WebContents>(contents),
+        content::NotificationService::NoDetails());
+  }
+
+  // Generates a paint notification for the given tab.
+  void GenerateRenderWidgetHostDidUpdateBackingStore(size_t tab_index) {
+    content::WebContents* contents = restored_tabs_[tab_index].contents();
+    content::RenderWidgetHost* host =
+        contents->GetRenderWidgetHostView()->GetRenderWidgetHost();
+    stats_collector_->Observe(
+        content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
+        content::Source<content::RenderWidgetHost>(host),
+        content::NotificationService::NoDetails());
+  }
+
+  // Defers a tab.
+  void DeferTab(size_t tab_index) {
+    content::WebContents* contents = restored_tabs_[tab_index].contents();
+    content::NavigationController* controller = &contents->GetController();
+    stats_collector_->DeferTab(controller);
+  }
+
+  // Generates mock call expectation to ReportTabLoaderStats, with the given
+  // configuration for the statistics.
+  void ExpectReportTabLoaderStats(
+      MockStatsReportingDelegate* mock_reporting_delegate,
+      size_t tab_count,
+      size_t tabs_loaded,
+      int foreground_tab_first_loaded_ms,
+      int foreground_tab_first_paint_ms,
+      int non_deferred_tabs_loaded_ms,
+      size_t parallel_tab_loads) {
+    EXPECT_CALL(*mock_reporting_delegate, ReportTabLoaderStats(
+        AllOf(Field(&TabLoaderStats::tab_count, Eq(tab_count)),
+              Field(&TabLoaderStats::tabs_loaded, Eq(tabs_loaded)),
+              Field(&TabLoaderStats::foreground_tab_first_loaded,
+                    Eq(base::TimeDelta::FromMilliseconds(
+                        foreground_tab_first_loaded_ms))),
+              Field(&TabLoaderStats::foreground_tab_first_paint,
+                    Eq(base::TimeDelta::FromMilliseconds(
+                        foreground_tab_first_paint_ms))),
+              Field(&TabLoaderStats::non_deferred_tabs_loaded,
+                    Eq(base::TimeDelta::FromMilliseconds(
+                        non_deferred_tabs_loaded_ms))),
+              Field(&TabLoaderStats::parallel_tab_loads,
+                    Eq(parallel_tab_loads)))));
+  }
+
+  // Inputs to the stats collector. Reset prior to each test.
+  base::SimpleTestTickClock* test_tick_clock_;
+  std::vector<RestoredTab> restored_tabs_;
+
+  // Infrastructure needed for using the TestWebContentsFactory. These are
+  // initialized once by the fixture and reused across unittests.
+  base::MessageLoop message_loop_;
+  TestingProfile testing_profile_;
+  content::TestBrowserThread ui_thread_;
+
+  // A new web contents factory is generated per test. This automatically cleans
+  // up any tabs created by previous tests.
+  scoped_ptr<content::TestWebContentsFactory> test_web_contents_factory_;
+
+  // These are recreated for each test. The reporting delegate allows the test
+  // to observe the behaviour of the SessionRestoreStatsCollector under test.
+  PassthroughStatsReportingDelegate* passthrough_reporting_delegate_;
+  TestSessionRestoreStatsCollector* stats_collector_;
+};
+
+TEST_F(SessionRestoreStatsCollectorTest, SingleTabPaintBeforeLoad) {
+  MockStatsReportingDelegate mock_reporting_delegate;
+  passthrough_reporting_delegate_->set_reporting_delegate(
+      &mock_reporting_delegate);
+
+  CreateRestoredTab(true);
+  stats_collector_->TrackTabs(restored_tabs_);
+
+  Tick();  // 1ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(0);
+
+  ExpectReportTabLoaderStats(&mock_reporting_delegate, 1, 1, 2, 1, 2, 1);
+  EXPECT_CALL(mock_reporting_delegate, ReportStatsCollectorDeath());
+
+  Tick();  // 2ms.
+  GenerateLoadStop(0);
+}
+
+TEST_F(SessionRestoreStatsCollectorTest, SingleTabPaintAfterLoad) {
+  MockStatsReportingDelegate mock_reporting_delegate;
+  passthrough_reporting_delegate_->set_reporting_delegate(
+      &mock_reporting_delegate);
+
+  CreateRestoredTab(true);
+  stats_collector_->TrackTabs(restored_tabs_);
+
+  Tick();  // 1ms.
+  GenerateLoadStop(0);
+
+  ExpectReportTabLoaderStats(&mock_reporting_delegate, 1, 1, 1, 2, 1, 1);
+  EXPECT_CALL(mock_reporting_delegate, ReportStatsCollectorDeath());
+
+  Tick();  // 2ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(0);
+}
+
+TEST_F(SessionRestoreStatsCollectorTest, MultipleTabsLoadSerially) {
+  MockStatsReportingDelegate mock_reporting_delegate;
+  passthrough_reporting_delegate_->set_reporting_delegate(
+      &mock_reporting_delegate);
+
+  CreateRestoredTab(true);
+  CreateRestoredTab(false);
+  CreateRestoredTab(false);
+  stats_collector_->TrackTabs(restored_tabs_);
+
+  // Foreground tab paints then finishes loading.
+  Tick();  // 1ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(0);
+  Tick();  // 2ms.
+  GenerateLoadStop(0);
+
+  // First background tab starts loading, paints, then finishes loading.
+  Tick();  // 3ms.
+  GenerateLoadStart(1);
+  Tick();  // 4ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(1);
+  Tick();  // 5ms.
+  GenerateLoadStop(1);
+
+  // Second background tab starts loading, finishes loading, but never paints.
+  Tick();  // 6ms.
+  GenerateLoadStart(2);
+
+  ExpectReportTabLoaderStats(&mock_reporting_delegate, 3, 3, 2, 1, 7, 1);
+  EXPECT_CALL(mock_reporting_delegate, ReportStatsCollectorDeath());
+
+  Tick();  // 7ms.
+  GenerateLoadStop(2);
+}
+
+TEST_F(SessionRestoreStatsCollectorTest, MultipleTabsLoadSimultaneously) {
+  MockStatsReportingDelegate mock_reporting_delegate;
+  passthrough_reporting_delegate_->set_reporting_delegate(
+      &mock_reporting_delegate);
+
+  CreateRestoredTab(true);
+  CreateRestoredTab(false);
+  CreateRestoredTab(false);
+  stats_collector_->TrackTabs(restored_tabs_);
+
+  // Foreground tab paints then finishes loading.
+  Tick();  // 1ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(0);
+  Tick();  // 2ms.
+  GenerateLoadStop(0);
+
+  // Both background tabs start loading at the same time. The first one paints
+  // before finishing loading, the second one paints after finishing loading
+  // (the stats collector never sees the paint event).
+  Tick();  // 3ms.
+  GenerateLoadStart(1);
+  GenerateLoadStart(2);
+  Tick();  // 4ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(1);
+  Tick();  // 5ms.
+  GenerateLoadStop(1);
+
+  ExpectReportTabLoaderStats(&mock_reporting_delegate, 3, 3, 2, 1, 6, 2);
+  EXPECT_CALL(mock_reporting_delegate, ReportStatsCollectorDeath());
+
+  Tick();  // 6ms.
+  GenerateLoadStop(2);
+}
+
+TEST_F(SessionRestoreStatsCollectorTest, DeferredTabs) {
+  MockStatsReportingDelegate mock_reporting_delegate;
+  passthrough_reporting_delegate_->set_reporting_delegate(
+      &mock_reporting_delegate);
+
+  CreateRestoredTab(true);
+  CreateRestoredTab(false);
+  stats_collector_->TrackTabs(restored_tabs_);
+
+  // Foreground tab paints, then the background tab is deferred.
+  Tick();  // 1ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(0);
+  EXPECT_CALL(mock_reporting_delegate, ReportTabDeferred());
+  DeferTab(1);
+  testing::Mock::VerifyAndClearExpectations(&mock_reporting_delegate);
+
+  // Foreground tab finishes loading and stats get reported.
+  ExpectReportTabLoaderStats(&mock_reporting_delegate, 2, 1, 2, 1, 2, 1);
+  Tick();  // 2ms.
+  GenerateLoadStop(0);
+  testing::Mock::VerifyAndClearExpectations(&mock_reporting_delegate);
+
+  // Background tab starts loading, paints and stops loading. This fires off a
+  // deferred tab loaded notification.
+  Tick();  // 3ms.
+  GenerateLoadStart(1);
+  Tick();  // 4ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(1);
+  EXPECT_CALL(mock_reporting_delegate, ReportDeferredTabLoaded());
+  EXPECT_CALL(mock_reporting_delegate, ReportStatsCollectorDeath());
+  Tick();  // 5ms.
+  GenerateLoadStop(1);
+}
+
+TEST_F(SessionRestoreStatsCollectorTest, FocusSwitchNoForegroundPaintOrLoad) {
+  MockStatsReportingDelegate mock_reporting_delegate;
+  passthrough_reporting_delegate_->set_reporting_delegate(
+      &mock_reporting_delegate);
+
+  CreateRestoredTab(true);
+  stats_collector_->TrackTabs(restored_tabs_);
+
+  // Create another tab and make it the foreground tab. This tab is not actually
+  // being tracked by the SessionRestoreStatsCollector, but its paint events
+  // will be observed.
+  CreateRestoredTab(false);
+  Hide(0);
+  Show(1);
+
+  // Load and paint the restored tab (now the background tab). Don't expect
+  // any calls to the mock as a visible tab paint has not yet been observed.
+  Tick();  // 1ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(0);
+  Tick();  // 2ms.
+  GenerateLoadStop(0);
+  testing::Mock::VerifyAndClearExpectations(&mock_reporting_delegate);
+
+  // Mark the new foreground tab as having painted. This should cause the
+  // stats to be emitted, but with empty foreground paint and load values.
+  ExpectReportTabLoaderStats(&mock_reporting_delegate, 1, 1, 0, 0, 2, 1);
+  EXPECT_CALL(mock_reporting_delegate, ReportStatsCollectorDeath());
+  Tick();  // 3ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(1);
+}
+
+TEST_F(SessionRestoreStatsCollectorTest, FocusSwitchNoForegroundPaint) {
+  MockStatsReportingDelegate mock_reporting_delegate;
+  passthrough_reporting_delegate_->set_reporting_delegate(
+      &mock_reporting_delegate);
+
+  CreateRestoredTab(true);
+  stats_collector_->TrackTabs(restored_tabs_);
+
+  // Load the foreground tab.
+  Tick();  // 1ms.
+  GenerateLoadStop(0);
+
+  // Create another tab and make it the foreground tab. This tab is not actually
+  // being tracked by the SessionRestoreStatsCollector, but its paint events
+  // will still be observed.
+  CreateRestoredTab(false);
+  Hide(0);
+  Show(1);
+
+  // Load and paint the restored tab (now the background tab). Don't expect
+  // any calls to the mock as a visible tab paint has not yet been observed.
+  Tick();  // 2ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(0);
+  testing::Mock::VerifyAndClearExpectations(&mock_reporting_delegate);
+
+  // Mark the new foreground tab as having painted. This should cause the
+  // stats to be emitted, but with an empty foreground paint value.
+  ExpectReportTabLoaderStats(&mock_reporting_delegate, 1, 1, 1, 0, 1, 1);
+  EXPECT_CALL(mock_reporting_delegate, ReportStatsCollectorDeath());
+  Tick();  // 3ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(1);
+}
+
+TEST_F(SessionRestoreStatsCollectorTest, LoadingTabDestroyedBeforePaint) {
+  MockStatsReportingDelegate mock_reporting_delegate;
+  passthrough_reporting_delegate_->set_reporting_delegate(
+      &mock_reporting_delegate);
+
+  CreateRestoredTab(true);
+  stats_collector_->TrackTabs(restored_tabs_);
+
+  // Destroy the tab. Expect all timings to be zero.
+  ExpectReportTabLoaderStats(&mock_reporting_delegate, 1, 0, 0, 0, 0, 1);
+  EXPECT_CALL(mock_reporting_delegate, ReportStatsCollectorDeath());
+  GenerateWebContentsDestroyed(0);
+}
+
+TEST_F(SessionRestoreStatsCollectorTest, LoadingTabDestroyedAfterPaint) {
+  MockStatsReportingDelegate mock_reporting_delegate;
+  passthrough_reporting_delegate_->set_reporting_delegate(
+      &mock_reporting_delegate);
+
+  CreateRestoredTab(true);
+  stats_collector_->TrackTabs(restored_tabs_);
+
+  Tick();  // 1 ms.
+  GenerateRenderWidgetHostDidUpdateBackingStore(0);
+
+  // Destroy the tab. Expect both load timings to be zero.
+  ExpectReportTabLoaderStats(&mock_reporting_delegate, 1, 0, 0, 1, 0, 1);
+  EXPECT_CALL(mock_reporting_delegate, ReportStatsCollectorDeath());
+  GenerateWebContentsDestroyed(0);
+}