Revert "Revert "Add startup tests that log start script, domcontentloaded, and onload.""

This reverts commit r28209 and relands r28199.

The failure seems to have been flaky (it passed on the other bots and on the following run).  I want to
try to land again.  If it fails again, I'll disable the test.

TBR=mattm

Review URL: http://codereview.chromium.org/268003

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@28268 0039d316-1c4b-4281-b951-d872f2087c98

15 files changed, 210 insertions, 28 deletions

diff --git a/chrome/browser/automation/automation_provider.cc b/chrome/browser/automation/automation_provider.cc
index 38b732e..89a8ec9 100644
--- a/chrome/browser/automation/automation_provider.cc
+++ b/chrome/browser/automation/automation_provider.cc
@@ -133,6 +133,7 @@ AutomationProvider::AutomationProvider(Profile* profile)
       new AutomationAutocompleteEditTracker(this));
   new_tab_ui_load_observer_.reset(new NewTabUILoadObserver(this));
   dom_operation_observer_.reset(new DomOperationNotificationObserver(this));
+  metric_event_duration_observer_.reset(new MetricEventDurationObserver());
 }
 
 AutomationProvider::~AutomationProvider() {
@@ -356,6 +357,8 @@ void AutomationProvider::OnMessageReceived(const IPC::Message& message) {
 #endif
     IPC_MESSAGE_HANDLER(AutomationMsg_GetSecurityState, GetSecurityState)
     IPC_MESSAGE_HANDLER(AutomationMsg_GetPageType, GetPageType)
+    IPC_MESSAGE_HANDLER(AutomationMsg_GetMetricEventDuration,
+                        GetMetricEventDuration)
     IPC_MESSAGE_HANDLER_DELAY_REPLY(AutomationMsg_ActionOnSSLBlockingPage,
                                     ActionOnSSLBlockingPage)
     IPC_MESSAGE_HANDLER(AutomationMsg_BringBrowserToFront, BringBrowserToFront)
@@ -1443,6 +1446,12 @@ void AutomationProvider::GetPageType(int handle, bool* success,
   }
 }
 
+void AutomationProvider::GetMetricEventDuration(const std::string& event_name,
+                                                int* duration_ms) {
+  *duration_ms = metric_event_duration_observer_->GetEventDurationMs(
+      event_name);
+}
+
 void AutomationProvider::ActionOnSSLBlockingPage(int handle, bool proceed,
                                                  IPC::Message* reply_message) {
   if (tab_tracker_->ContainsHandle(handle)) {
diff --git a/chrome/browser/automation/automation_provider.h b/chrome/browser/automation/automation_provider.h
index ef1f228..4ebe00e 100644
--- a/chrome/browser/automation/automation_provider.h
+++ b/chrome/browser/automation/automation_provider.h
@@ -40,10 +40,11 @@ struct Reposition_Params;
 struct ExternalTabSettings;
 }
 
+class ExtensionPortContainer;
+class ExternalTabContainer;
 class LoginHandler;
+class MetricEventDurationObserver;
 class NavigationControllerRestoredObserver;
-class ExternalTabContainer;
-class ExtensionPortContainer;
 struct AutocompleteMatchData;
 
 namespace gfx {
@@ -337,6 +338,10 @@ class AutomationProvider : public base::RefCounted<AutomationProvider>,
   void GetPageType(int handle, bool* success,
                    NavigationEntry::PageType* page_type);
 
+  // Gets the duration in ms of the last event matching |event_name|.
+  // |duration_ms| is -1 if the event hasn't occurred yet.
+  void GetMetricEventDuration(const std::string& event_name, int* duration_ms);
+
   // Simulates an action on the SSL blocking page at the tab specified by
   // |handle|. If |proceed| is true, it is equivalent to the user pressing the
   // 'Proceed' button, if false the 'Get me out of there button'.
@@ -510,6 +515,7 @@ class AutomationProvider : public base::RefCounted<AutomationProvider>,
   scoped_ptr<NotificationObserver> find_in_page_observer_;
   scoped_ptr<NotificationObserver> dom_operation_observer_;
   scoped_ptr<NotificationObserver> dom_inspector_observer_;
+  scoped_ptr<MetricEventDurationObserver> metric_event_duration_observer_;
   scoped_ptr<AutomationBrowserTracker> browser_tracker_;
   scoped_ptr<AutomationTabTracker> tab_tracker_;
   scoped_ptr<AutomationWindowTracker> window_tracker_;
diff --git a/chrome/browser/automation/automation_provider_observers.cc b/chrome/browser/automation/automation_provider_observers.cc
index 57fe3e7..9250ec8 100644
--- a/chrome/browser/automation/automation_provider_observers.cc
+++ b/chrome/browser/automation/automation_provider_observers.cc
@@ -9,13 +9,15 @@
 #include "chrome/browser/automation/automation_provider.h"
 #include "chrome/browser/dom_operation_notification_details.h"
 #include "chrome/browser/login_prompt.h"
-#if defined(OS_WIN)
-#include "chrome/browser/printing/print_job.h"
-#endif  // defined(OS_WIN)
+#include "chrome/browser/metrics/metric_event_duration_details.h"
 #include "chrome/browser/tab_contents/navigation_controller.h"
 #include "chrome/browser/tab_contents/tab_contents.h"
 #include "chrome/common/notification_service.h"
 
+#if defined(OS_WIN)
+#include "chrome/browser/printing/print_job.h"
+#endif  // defined(OS_WIN)
+
 InitialLoadObserver::InitialLoadObserver(size_t tab_count,
                                          AutomationProvider* automation)
     : automation_(automation),
@@ -628,3 +630,28 @@ void DocumentPrintedNotificationObserver::Observe(
   }
 }
 #endif  // defined(OS_WIN)
+
+MetricEventDurationObserver::MetricEventDurationObserver() {
+  registrar_.Add(this, NotificationType::METRIC_EVENT_DURATION,
+                 NotificationService::AllSources());
+}
+
+int MetricEventDurationObserver::GetEventDurationMs(
+    const std::string& event_name) {
+  EventDurationMap::const_iterator it = durations_.find(event_name);
+  if (it == durations_.end())
+    return -1;
+  return it->second;
+}
+
+void MetricEventDurationObserver::Observe(NotificationType type,
+    const NotificationSource& source, const NotificationDetails& details) {
+  if (type != NotificationType::METRIC_EVENT_DURATION) {
+    NOTREACHED();
+    return;
+  }
+  MetricEventDurationDetails* metric_event_duration =
+      Details<MetricEventDurationDetails>(details).ptr();
+  durations_[metric_event_duration->event_name] =
+      metric_event_duration->duration_ms;
+}
diff --git a/chrome/browser/automation/automation_provider_observers.h b/chrome/browser/automation/automation_provider_observers.h
index 2dd596e..5719582 100644
--- a/chrome/browser/automation/automation_provider_observers.h
+++ b/chrome/browser/automation/automation_provider_observers.h
@@ -5,6 +5,7 @@
 #ifndef CHROME_BROWSER_AUTOMATION_AUTOMATION_PROVIDER_OBSERVERS_H_
 #define CHROME_BROWSER_AUTOMATION_AUTOMATION_PROVIDER_OBSERVERS_H_
 
+#include <map>
 #include <set>
 
 #include "chrome/common/notification_observer.h"
@@ -338,4 +339,25 @@ class DocumentPrintedNotificationObserver : public NotificationObserver {
 };
 #endif  // defined(OS_WIN)
 
+// Collects METRIC_EVENT_DURATION notifications and keep track of the times.
+class MetricEventDurationObserver : public NotificationObserver {
+ public:
+  MetricEventDurationObserver();
+
+  // Get the duration of an event.  Returns -1 if we haven't seen the event.
+  int GetEventDurationMs(const std::string& event_name);
+
+  // NotificationObserver interface.
+  virtual void Observe(NotificationType type, const NotificationSource& source,
+                       const NotificationDetails& details);
+
+ private:
+  NotificationRegistrar registrar_;
+
+  typedef std::map<std::string, int> EventDurationMap;
+  EventDurationMap durations_;
+
+  DISALLOW_COPY_AND_ASSIGN(MetricEventDurationObserver);
+};
+
 #endif  // CHROME_BROWSER_AUTOMATION_AUTOMATION_PROVIDER_OBSERVERS_H_
diff --git a/chrome/browser/metrics/metric_event_duration_details.h b/chrome/browser/metrics/metric_event_duration_details.h
new file mode 100644
index 0000000..3e2feec
--- /dev/null
+++ b/chrome/browser/metrics/metric_event_duration_details.h
@@ -0,0 +1,20 @@
+// Copyright (c) 2009 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.
+
+#ifndef CHROME_BROWSER_METRICS_METRIC_EVENT_DURATION_DETAILS_H_
+#define CHROME_BROWSER_METRICS_METRIC_EVENT_DURATION_DETAILS_H_
+
+#include <string>
+
+// Used when sending a notification about an event that occurred that we want
+// to time.
+struct MetricEventDurationDetails {
+  MetricEventDurationDetails(const std::string& e, int d)
+      : event_name(e), duration_ms(d) {}
+
+  std::string event_name;
+  int duration_ms;
+};
+
+#endif  // CHROME_BROWSER_METRICS_METRIC_EVENT_DURATION_DETAILS_H_
diff --git a/chrome/browser/tab_contents/tab_contents.cc b/chrome/browser/tab_contents/tab_contents.cc
index 7735a14..325e6bc 100644
--- a/chrome/browser/tab_contents/tab_contents.cc
+++ b/chrome/browser/tab_contents/tab_contents.cc
@@ -32,6 +32,7 @@
 #include "chrome/browser/jsmessage_box_handler.h"
 #include "chrome/browser/load_from_memory_cache_details.h"
 #include "chrome/browser/load_notification_details.h"
+#include "chrome/browser/metrics/metric_event_duration_details.h"
 #include "chrome/browser/modal_html_dialog_delegate.h"
 #include "chrome/browser/omnibox_search_hint.h"
 #include "chrome/browser/password_manager/password_manager.h"
@@ -1177,6 +1178,9 @@ void TabContents::LogNewTabTime(const std::string& event_name) {
     return;
 
   base::TimeDelta duration = base::TimeTicks::Now() - new_tab_start_time_;
+  MetricEventDurationDetails details(event_name,
+      static_cast<int>(duration.InMilliseconds()));
+
   if (event_name == "NewTab.ScriptStart") {
     UMA_HISTOGRAM_TIMES("NewTab.ScriptStart", duration);
   } else if (event_name == "NewTab.DOMContentLoaded") {
@@ -1185,7 +1189,13 @@ void TabContents::LogNewTabTime(const std::string& event_name) {
     UMA_HISTOGRAM_TIMES("NewTab.Onload", duration);
     // The new tab page has finished loading; reset it.
     new_tab_start_time_ = base::TimeTicks();
+  } else {
+    NOTREACHED();
   }
+  NotificationService::current()->Notify(
+      NotificationType::METRIC_EVENT_DURATION,
+      Source<TabContents>(this),
+      Details<MetricEventDurationDetails>(&details));
 }
 
 // Notifies the RenderWidgetHost instance about the fact that the page is
diff --git a/chrome/chrome.gyp b/chrome/chrome.gyp
index 20517d4..2a02225 100755
--- a/chrome/chrome.gyp
+++ b/chrome/chrome.gyp
@@ -1639,6 +1639,7 @@
         'browser/memory_purger.h',
         'browser/meta_table_helper.cc',
         'browser/meta_table_helper.h',
+        'browser/metrics/metric_event_duration_details.h',
         'browser/metrics/metrics_log.cc',
         'browser/metrics/metrics_log.h',
         'browser/metrics/metrics_response.cc',
diff --git a/chrome/common/notification_type.h b/chrome/common/notification_type.h
index 75d5caf..2a1487c 100644
--- a/chrome/common/notification_type.h
+++ b/chrome/common/notification_type.h
@@ -314,6 +314,11 @@ class NotificationType {
     // starting and finishing all painting.
     INITIAL_NEW_TAB_UI_LOAD,
 
+    // Used to fire notifications about how long various events took to
+    // complete.  E.g., this is used to get more fine grained timings from the
+    // new tab page.  Details is a MetricEventDurationDetails.
+    METRIC_EVENT_DURATION,
+
     // This notification is sent when a TabContents is being hidden, e.g. due
     // to switching away from this tab.  The source is a Source<TabContents>.
     TAB_CONTENTS_HIDDEN,
diff --git a/chrome/test/automation/automation_messages_internal.h b/chrome/test/automation/automation_messages_internal.h
index c9d04dd..5d009b5 100644
--- a/chrome/test/automation/automation_messages_internal.h
+++ b/chrome/test/automation/automation_messages_internal.h
@@ -1113,4 +1113,10 @@ IPC_BEGIN_MESSAGES(Automation)
                       int /* tab_handle */,
                       int /* The font size */)
 
+  // Returns a metric event duration that was last recorded.  Returns -1 if the
+  // event hasn't occurred yet.
+  IPC_SYNC_MESSAGE_ROUTED1_1(AutomationMsg_GetMetricEventDuration,
+                             std::string /* event_name */,
+                             int /* duration ms */)
+
 IPC_END_MESSAGES(Automation)
diff --git a/chrome/test/automation/automation_proxy.cc b/chrome/test/automation/automation_proxy.cc
index a039ffb3..69a363c 100644
--- a/chrome/test/automation/automation_proxy.cc
+++ b/chrome/test/automation/automation_proxy.cc
@@ -342,6 +342,12 @@ bool AutomationProxy::IsURLDisplayed(GURL url) {
   return false;
 }
 
+bool AutomationProxy::GetMetricEventDuration(const std::string& event_name,
+                                             int* duration_ms) {
+  return Send(new AutomationMsg_GetMetricEventDuration(0, event_name,
+                                                       duration_ms));
+}
+
 bool AutomationProxy::SetFilteredInet(bool enabled) {
   return Send(new AutomationMsg_SetFilteredInet(0, enabled));
 }
diff --git a/chrome/test/automation/automation_proxy.h b/chrome/test/automation/automation_proxy.h
index dac3bc3..ce3ff17 100644
--- a/chrome/test/automation/automation_proxy.h
+++ b/chrome/test/automation/automation_proxy.h
@@ -124,6 +124,10 @@ class AutomationProxy : public IPC::Channel::Listener,
   // Returns true if one of the tabs in any window displays given url.
   bool IsURLDisplayed(GURL url);
 
+  // Get the duration of the last |event_name| in the browser.  Returns
+  // false if the IPC failed to send.
+  bool GetMetricEventDuration(const std::string& event_name, int* duration_ms);
+
   // Returns the BrowserProxy for the browser window at the given index,
   // transferring ownership of the pointer to the caller.
   // On failure, returns NULL.
diff --git a/chrome/test/startup/feature_startup_test.cc b/chrome/test/startup/feature_startup_test.cc
index 574b283..5743e35 100644
--- a/chrome/test/startup/feature_startup_test.cc
+++ b/chrome/test/startup/feature_startup_test.cc
@@ -39,11 +39,7 @@ class NewTabUIStartupTest : public UITest {
     PrintResultList("new_tab", "", label, times, "ms", important);
   }
 
-  // Run the test, by bringing up a browser and timing the new tab startup.
-  // |want_warm| is true if we should output warm-disk timings, false if
-  // we should report cold timings.
-  void RunStartupTest(const char* label, bool want_warm, bool important,
-                      int profile_type) {
+  void InitProfile(UITest::ProfileType profile_type) {
     profile_type_ = profile_type;
 
     // Install the location of the test profile file.
@@ -53,6 +49,14 @@ class NewTabUIStartupTest : public UITest {
     // Disable the first run notification because it has an animation which
     // masks any real performance regressions.
     launch_arguments_.AppendSwitch(switches::kDisableNewTabFirstRun);
+  }
+
+  // Run the test, by bringing up a browser and timing the new tab startup.
+  // |want_warm| is true if we should output warm-disk timings, false if
+  // we should report cold timings.
+  void RunStartupTest(const char* label, bool want_warm, bool important,
+                      UITest::ProfileType profile_type) {
+    InitProfile(profile_type);
 
     TimeDelta timings[kNumCycles];
     for (int i = 0; i < kNumCycles; ++i) {
@@ -66,9 +70,9 @@ class NewTabUIStartupTest : public UITest {
       // We resize the window so that we hit the normal layout of the NTP and
       // not the small layout mode.
 #if defined(OS_WIN)
-// TODO(port): SetBounds returns false when not implemented.
-// It is OK to comment out the resize since it will still be useful to test the
-// default size of the window.
+      // TODO(port): SetBounds returns false when not implemented.
+      // It is OK to comment out the resize since it will still be useful to
+      // test the default size of the window.
       ASSERT_TRUE(window->GetWindow().get()->SetBounds(gfx::Rect(1000, 1000)));
 #endif
       int tab_count = -1;
@@ -80,15 +84,14 @@ class NewTabUIStartupTest : public UITest {
       ASSERT_TRUE(window->WaitForTabCountToBecome(2, 5000));
       int load_time;
       ASSERT_TRUE(automation()->WaitForInitialNewTabUILoad(&load_time));
-      timings[i] = TimeDelta::FromMilliseconds(load_time);
 
       if (want_warm) {
         // Bring up a second tab, now that we've already shown one tab.
         window->ApplyAccelerator(IDC_NEW_TAB);
         ASSERT_TRUE(window->WaitForTabCountToBecome(3, 5000));
         ASSERT_TRUE(automation()->WaitForInitialNewTabUILoad(&load_time));
-        timings[i] = TimeDelta::FromMilliseconds(load_time);
       }
+      timings[i] = TimeDelta::FromMilliseconds(load_time);
 
       window = NULL;
       UITest::TearDown();
@@ -96,6 +99,65 @@ class NewTabUIStartupTest : public UITest {
 
     PrintTimings(label, timings, important);
   }
+
+  void RunNewTabTimingTest() {
+    InitProfile(UITest::DEFAULT_THEME);
+
+    TimeDelta scriptstart_times[kNumCycles];
+    TimeDelta domcontentloaded_times[kNumCycles];
+    TimeDelta onload_times[kNumCycles];
+
+    for (int i = 0; i < kNumCycles; ++i) {
+      UITest::SetUp();
+
+      // Switch to the "new tab" tab, which should be any new tab after the
+      // first (the first is about:blank).
+      scoped_refptr<BrowserProxy> window(automation()->GetBrowserWindow(0));
+      ASSERT_TRUE(window.get());
+
+      // We resize the window so that we hit the normal layout of the NTP and
+      // not the small layout mode.
+#if defined(OS_WIN)
+      // TODO(port): SetBounds returns false when not implemented.
+      // It is OK to comment out the resize since it will still be useful to
+      // test the default size of the window.
+      ASSERT_TRUE(window->GetWindow().get()->SetBounds(gfx::Rect(1000, 1000)));
+#endif
+      int tab_count = -1;
+      ASSERT_TRUE(window->GetTabCount(&tab_count));
+      ASSERT_EQ(1, tab_count);
+
+      // Hit ctl-t and wait for the tab to load.
+      window->ApplyAccelerator(IDC_NEW_TAB);
+      ASSERT_TRUE(window->WaitForTabCountToBecome(2, 5000));
+      int duration;
+      ASSERT_TRUE(automation()->WaitForInitialNewTabUILoad(&duration));
+
+      // Collect the timing information.
+      ASSERT_TRUE(automation()->GetMetricEventDuration("NewTab.ScriptStart",
+          &duration));
+      ASSERT_NE(duration, -1);
+      scriptstart_times[i] = TimeDelta::FromMilliseconds(duration);
+
+      ASSERT_TRUE(automation()->GetMetricEventDuration(
+          "NewTab.DOMContentLoaded", &duration));
+      ASSERT_NE(duration, -1);
+      domcontentloaded_times[i] = TimeDelta::FromMilliseconds(duration);
+
+      ASSERT_TRUE(automation()->GetMetricEventDuration("NewTab.Onload",
+          &duration));
+      ASSERT_NE(duration, -1);
+      onload_times[i] = TimeDelta::FromMilliseconds(duration);
+
+      window = NULL;
+      UITest::TearDown();
+    }
+
+    PrintTimings("script_start", scriptstart_times, false /* important */);
+    PrintTimings("domcontent_loaded", domcontentloaded_times,
+                 false /* important */);
+    PrintTimings("onload", onload_times, false /* important */);
+  }
 };
 
 // TODO(pamg): run these tests with a reference build?
@@ -115,6 +177,10 @@ TEST_F(NewTabUIStartupTest, ComplexThemeCold) {
                  UITest::COMPLEX_THEME);
 }
 
+TEST_F(NewTabUIStartupTest, NewTabTimingTestsCold) {
+  RunNewTabTimingTest();
+}
+
 #if defined(OS_LINUX)
 TEST_F(NewTabUIStartupTest, GtkThemeCold) {
   RunStartupTest("tab_gtk_theme_cold", false /* cold */,
diff --git a/chrome/test/startup/startup_test.cc b/chrome/test/startup/startup_test.cc
index 69035d8..7e52741 100644
--- a/chrome/test/startup/startup_test.cc
+++ b/chrome/test/startup/startup_test.cc
@@ -50,7 +50,7 @@ class StartupTest : public UITest {
   }
 
   void RunStartupTest(const char* graph, const char* trace,
-      bool test_cold, bool important, int profile_type) {
+      bool test_cold, bool important, UITest::ProfileType profile_type) {
     profile_type_ = profile_type;
 
     // Sets the profile data for the run.  For now, this is only used for
diff --git a/chrome/test/ui/ui_test.cc b/chrome/test/ui/ui_test.cc
index 30ed274..8308ca0 100644
--- a/chrome/test/ui/ui_test.cc
+++ b/chrome/test/ui/ui_test.cc
@@ -924,7 +924,7 @@ void UITest::RewritePreferencesFile(const FilePath& user_data_dir) {
 }
 
 // static
-FilePath UITest::ComputeTypicalUserDataSource(int profile_type) {
+FilePath UITest::ComputeTypicalUserDataSource(ProfileType profile_type) {
   FilePath source_history_file;
   EXPECT_TRUE(PathService::Get(chrome::DIR_TEST_DATA,
                                &source_history_file));
diff --git a/chrome/test/ui/ui_test.h b/chrome/test/ui/ui_test.h
index 5c45e8c..c87ffe1 100644
--- a/chrome/test/ui/ui_test.h
+++ b/chrome/test/ui/ui_test.h
@@ -362,9 +362,18 @@ class UITest : public testing::Test {
     log_level_ = value;
   }
 
+  // Profile theme type choices.
+  typedef enum {
+    DEFAULT_THEME = 0,
+    COMPLEX_THEME = 1,
+    NATIVE_THEME = 2,
+    CUSTOM_FRAME = 3,
+    CUSTOM_FRAME_NATIVE_THEME = 4,
+  } ProfileType;
+
   // Returns the directory name where the "typical" user data is that we use
   // for testing.
-  static FilePath ComputeTypicalUserDataSource(int profile_type);
+  static FilePath ComputeTypicalUserDataSource(ProfileType profile_type);
 
   // Rewrite the preferences file to point to the proper image directory.
   static void RewritePreferencesFile(const FilePath& user_data_dir);
@@ -443,15 +452,6 @@ class UITest : public testing::Test {
   void StartHttpServer(const FilePath& root_directory);
   void StopHttpServer();
 
-  // Profile theme type choices.
-  typedef enum {
-    DEFAULT_THEME = 0,
-    COMPLEX_THEME = 1,
-    NATIVE_THEME = 2,
-    CUSTOM_FRAME = 3,
-    CUSTOM_FRAME_NATIVE_THEME = 4,
-  } ProfileType;
-
  private:
   // Check that no processes related to Chrome exist, displaying
   // the given message if any do.
@@ -518,7 +518,7 @@ class UITest : public testing::Test {
   bool use_existing_browser_;           // Duplicate of the static version.
                                         // Default value comes from static.
   bool enable_file_cookies_;            // Enable file cookies, default is true.
-  int profile_type_;                    // Are we using a profile with a
+  ProfileType profile_type_;            // Are we using a profile with a
                                         // complex theme?
 
  private: