Add histograms that track how long it takes to open the new tab page.

This doesn't time all loads of the new tab page, just new foreground
tabs using ctrl+t or the plus button.  This includes the time it takes
to create the tab contents and logs the time until JS has started
executing, domcontentloaded, and onload.

Note: onload doesn't mean the page is done loading.  We have "NewTabUI load" for that.

BUG=23120

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

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

6 files changed, 68 insertions, 8 deletions

diff --git a/chrome/browser/browser.cc b/chrome/browser/browser.cc
index e0cc047..1223101 100644
--- a/chrome/browser/browser.cc
+++ b/chrome/browser/browser.cc
@@ -1512,8 +1512,14 @@ TabContents* Browser::AddBlankTab(bool foreground) {
 }
 
 TabContents* Browser::AddBlankTabAt(int index, bool foreground) {
-  return AddTabWithURL(GURL(chrome::kChromeUINewTabURL), GURL(),
-                       PageTransition::TYPED, foreground, index, false, NULL);
+  // Time new tab page creation time.  We keep track of the timing data in
+  // TabContents, but we want to include the time it takes to create the
+  // TabContents object too.
+  base::TimeTicks new_tab_start_time = base::TimeTicks::Now();
+  TabContents* tab_contents =  AddTabWithURL(GURL(chrome::kChromeUINewTabURL),
+      GURL(), PageTransition::TYPED, foreground, index, false, NULL);
+  tab_contents->set_new_tab_start_time(new_tab_start_time);
+  return tab_contents;
 }
 
 Browser* Browser::CreateNewStripWithContents(TabContents* detached_contents,
diff --git a/chrome/browser/dom_ui/new_tab_ui.cc b/chrome/browser/dom_ui/new_tab_ui.cc
index 2e44322..688377f 100644
--- a/chrome/browser/dom_ui/new_tab_ui.cc
+++ b/chrome/browser/dom_ui/new_tab_ui.cc
@@ -1546,6 +1546,9 @@ class MetricsHandler : public DOMMessageHandler {
   // Callback which records a user action.
   void HandleMetrics(const Value* content);
 
+  // Callback for the "logEventTime" message.
+  void HandleLogEventTime(const Value* content);
+
  private:
 
   DISALLOW_COPY_AND_ASSIGN(MetricsHandler);
@@ -1554,6 +1557,9 @@ class MetricsHandler : public DOMMessageHandler {
 void MetricsHandler::RegisterMessages() {
   dom_ui_->RegisterMessageCallback("metrics",
       NewCallback(this, &MetricsHandler::HandleMetrics));
+
+  dom_ui_->RegisterMessageCallback("logEventTime",
+      NewCallback(this, &MetricsHandler::HandleLogEventTime));
 }
 
 void MetricsHandler::HandleMetrics(const Value* content) {
@@ -1572,6 +1578,20 @@ void MetricsHandler::HandleMetrics(const Value* content) {
   }
 }
 
+void MetricsHandler::HandleLogEventTime(const Value* content) {
+  if (content && content->GetType() == Value::TYPE_LIST) {
+    const ListValue* list_value = static_cast<const ListValue*>(content);
+    Value* list_member;
+    if (list_value->Get(0, &list_member) &&
+        list_member->GetType() == Value::TYPE_STRING) {
+      std::string event_name;
+      if (list_member->GetAsString(&event_name)) {
+        dom_ui_->tab_contents()->LogNewTabTime(event_name);
+      }
+    }
+  }
+}
+
 ///////////////////////////////////////////////////////////////////////////////
 // NewTabPageSetHomepageHandler
 
diff --git a/chrome/browser/resources/new_new_tab.html b/chrome/browser/resources/new_new_tab.html
index f16df88..08c452a 100644
--- a/chrome/browser/resources/new_new_tab.html
+++ b/chrome/browser/resources/new_new_tab.html
@@ -13,9 +13,13 @@
 <script>
 // Logging info for benchmarking purposes.
 var log = [];
-function logEvent(name) {
+function logEvent(name, shouldLogTime) {
+  if (shouldLogTime) {
+    chrome.send('logEventTime', [name]);
+  }
   log.push([name, Date.now()]);
 }
+logEvent('NewTab.ScriptStart', true);
 
 var global = this;
 
@@ -50,8 +54,6 @@ registerCallback('recentlyClosedTabs');
 registerCallback('syncMessageChanged');
 registerCallback('tips');
 
-logEvent('log start');
-
 </script>
 <link rel="stylesheet" href="new_new_tab.css">
 <script>
diff --git a/chrome/browser/resources/new_new_tab.js b/chrome/browser/resources/new_new_tab.js
index 10c9eb9..add6213 100644
--- a/chrome/browser/resources/new_new_tab.js
+++ b/chrome/browser/resources/new_new_tab.js
@@ -1328,11 +1328,12 @@ $('list-checkbox').addEventListener('change',
 $('list-checkbox').addEventListener('keydown',
                                     getCheckboxHandler(Section.LIST));
 
-window.addEventListener('load', bind(logEvent, global, 'onload fired'));
+window.addEventListener('load', bind(logEvent, global, 'NewTab.Onload', true));
 window.addEventListener('load', onDataLoaded);
+
 window.addEventListener('resize', handleWindowResize);
-document.addEventListener('DOMContentLoaded', bind(logEvent, global,
-                                                   'domcontentloaded fired'));
+document.addEventListener('DOMContentLoaded',
+    bind(logEvent, global, 'NewTab.DOMContentLoaded', true));
 
 // Whether or not we should send the initial 'GetSyncMessage' to the backend
 // depends on the value of the attribue 'syncispresent' which the backend sets
diff --git a/chrome/browser/tab_contents/tab_contents.cc b/chrome/browser/tab_contents/tab_contents.cc
index c59ea35..6fd8877 100644
--- a/chrome/browser/tab_contents/tab_contents.cc
+++ b/chrome/browser/tab_contents/tab_contents.cc
@@ -1170,6 +1170,24 @@ bool TabContents::IsActiveEntry(int32 page_id) {
           active_entry->page_id() == page_id);
 }
 
+void TabContents::LogNewTabTime(const std::string& event_name) {
+  // Not all new tab pages get timed.  In those cases, we don't have a
+  // new_tab_start_time_.
+  if (new_tab_start_time_.is_null())
+    return;
+
+  base::TimeDelta duration = base::TimeTicks::Now() - new_tab_start_time_;
+  if (event_name == "NewTab.ScriptStart") {
+    UMA_HISTOGRAM_TIMES("NewTab.ScriptStart", duration);
+  } else if (event_name == "NewTab.DOMContentLoaded") {
+    UMA_HISTOGRAM_TIMES("NewTab.DOMContentLoaded", duration);
+  } else if (event_name == "NewTab.Onload") {
+    UMA_HISTOGRAM_TIMES("NewTab.Onload", duration);
+    // The new tab page has finished loading; reset it.
+    new_tab_start_time_ = base::TimeTicks();
+  }
+}
+
 // Notifies the RenderWidgetHost instance about the fact that the page is
 // loading, or done loading and calls the base implementation.
 void TabContents::SetIsLoading(bool is_loading,
diff --git a/chrome/browser/tab_contents/tab_contents.h b/chrome/browser/tab_contents/tab_contents.h
index 87aeb76..83613ba 100644
--- a/chrome/browser/tab_contents/tab_contents.h
+++ b/chrome/browser/tab_contents/tab_contents.h
@@ -617,6 +617,16 @@ class TabContents : public PageNavigator,
     opener_dom_ui_type_ = opener_dom_ui_type;
   }
 
+  // We want to time how long it takes to create a new tab page.  This method
+  // gets called as parts of the new tab page have loaded.
+  void LogNewTabTime(const std::string& event_name);
+
+  // Set the time when we started to create the new tab page.  This time is
+  // from before we created this TabContents.
+  void set_new_tab_start_time(const base::TimeTicks& time) {
+    new_tab_start_time_ = time;
+  }
+
  private:
   friend class NavigationController;
   // Used to access the child_windows_ (ConstrainedWindowList) for testing
@@ -1151,6 +1161,9 @@ class TabContents : public PageNavigator,
   // non-NULL and represent the DOMUI of the opening renderer.
   DOMUITypeID opener_dom_ui_type_;
 
+  // The time that we started to create the new tab page.
+  base::TimeTicks new_tab_start_time_;
+
   // ---------------------------------------------------------------------------
 
   DISALLOW_COPY_AND_ASSIGN(TabContents);