Report page load time for startup tests.

Add the following stats to startup tests:
* foreground_tab_load_complete - time it took for the foreground tab to load
* last_tab_load_complete - time it took for the last tab to load.

All of these are in ms relative to browser main entry.

Changes in Chrome:
Report tab load time using base::Time rather than base::TimeTicks since all times are relative to browser main entry.

BUG=317481

Review URL: https://codereview.chromium.org/62833008

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

6 files changed, 125 insertions, 14 deletions

diff --git a/components/startup_metric_utils/startup_metric_utils.cc b/components/startup_metric_utils/startup_metric_utils.cc
index 2a72b3a..beb41cd 100644
--- a/components/startup_metric_utils/startup_metric_utils.cc
+++ b/components/startup_metric_utils/startup_metric_utils.cc
@@ -40,6 +40,34 @@ base::Lock* GetSubsystemStartupTimeHashLock() {
   return slow_startup_time_hash_lock;
 }
 
+// Record time of main entry so it can be read from Telemetry performance
+// tests.
+// TODO(jeremy): Remove once crbug.com/317481 is fixed.
+void RecordMainEntryTimeHistogram() {
+  const int kLowWordMask = 0xFFFFFFFF;
+  const int kLower31BitsMask = 0x7FFFFFFF;
+  base::TimeDelta browser_main_entry_time_absolute =
+      base::TimeDelta::FromMilliseconds(
+          MainEntryPointTimeInternal()->ToInternalValue() / 1000.0);
+
+  uint64 browser_main_entry_time_raw_ms =
+      browser_main_entry_time_absolute.InMilliseconds();
+
+  base::TimeDelta browser_main_entry_time_raw_ms_high_word =
+      base::TimeDelta::FromMilliseconds(
+          (browser_main_entry_time_raw_ms >> 32) & kLowWordMask);
+  // Shift by one because histograms only support non-negative values.
+  base::TimeDelta browser_main_entry_time_raw_ms_low_word =
+      base::TimeDelta::FromMilliseconds(
+          (browser_main_entry_time_raw_ms >> 1) & kLower31BitsMask);
+
+  // A timestamp is a 64 bit value, yet histograms can only store 32 bits.
+  HISTOGRAM_TIMES("Startup.BrowserMainEntryTimeAbsoluteHighWord",
+      browser_main_entry_time_raw_ms_high_word);
+  HISTOGRAM_TIMES("Startup.BrowserMainEntryTimeAbsoluteLowWord",
+      browser_main_entry_time_raw_ms_low_word);
+}
+
 bool g_main_entry_time_was_recorded = false;
 bool g_startup_stats_collection_finished = false;
 bool g_was_slow_startup = false;
@@ -88,6 +116,8 @@ const base::Time MainEntryStartTime() {
 }
 
 void OnBrowserStartupComplete(bool is_first_run) {
+  RecordMainEntryTimeHistogram();
+
   // Bail if uptime < 7 minutes, to filter out cases where Chrome may have been
   // autostarted and the machine is under io pressure.
   const int64 kSevenMinutesInMilliseconds =
diff --git a/content/renderer/stats_collection_controller.cc b/content/renderer/stats_collection_controller.cc
index 9f610ef..93734ab 100644
--- a/content/renderer/stats_collection_controller.cc
+++ b/content/renderer/stats_collection_controller.cc
@@ -50,25 +50,21 @@ bool CurrentRenderViewImpl(RenderViewImpl** out) {
 // either value may be null if a web contents hasn't fully loaded.
 // load_start_ms is represented as milliseconds since system boot.
 void ConvertLoadTimeToJSON(
-    const base::TimeTicks& load_start_time,
-    const base::TimeTicks& load_stop_time,
+    const base::Time& load_start_time,
+    const base::Time& load_stop_time,
     std::string *result) {
   base::DictionaryValue item;
 
   if (load_start_time.is_null()) {
-     item.Set("load_start_ms", base::Value::CreateNullValue());
+    item.Set("load_start_ms", base::Value::CreateNullValue());
   } else {
-    // This code relies on an implementation detail of TimeTicks::Now() - that
-    // its return value happens to coincide with the system uptime value in
-    // microseconds, on Win/Mac/iOS/Linux/ChromeOS and Android.  See comments
-    // in base::SysInfo::Uptime().
     item.SetDouble("load_start_ms", load_start_time.ToInternalValue() / 1000);
   }
   if (load_start_time.is_null() || load_stop_time.is_null()) {
     item.Set("load_duration_ms", base::Value::CreateNullValue());
   } else {
     item.SetDouble("load_duration_ms",
-        (load_stop_time - load_start_time).InMilliseconds());
+        (load_stop_time - load_start_time).InMillisecondsF());
   }
   base::JSONWriter::Write(&item, result);
 }
diff --git a/content/renderer/stats_collection_observer.cc b/content/renderer/stats_collection_observer.cc
index 00211ff..4c4b911 100644
--- a/content/renderer/stats_collection_observer.cc
+++ b/content/renderer/stats_collection_observer.cc
@@ -18,12 +18,12 @@ StatsCollectionObserver::~StatsCollectionObserver() {
 
 void StatsCollectionObserver::DidStartLoading() {
   DCHECK(start_time_.is_null());
-  start_time_ = base::TimeTicks::Now();
+  start_time_ = base::Time::Now();
 }
 
 void StatsCollectionObserver::DidStopLoading() {
   DCHECK(stop_time_.is_null());
-  stop_time_ = base::TimeTicks::Now();
+  stop_time_ = base::Time::Now();
 
   // Stop observing so we don't get called again.
   RenderViewImpl* impl = static_cast<RenderViewImpl*>(render_view());
diff --git a/content/renderer/stats_collection_observer.h b/content/renderer/stats_collection_observer.h
index 298226f..2717fd9 100644
--- a/content/renderer/stats_collection_observer.h
+++ b/content/renderer/stats_collection_observer.h
@@ -25,12 +25,12 @@ class StatsCollectionObserver : public RenderViewObserver {
 
   // Timing for the page load start and stop.  These functions may return
   // a null time value under various circumstances.
-  const base::TimeTicks& load_start_time() { return start_time_; }
-  const base::TimeTicks& load_stop_time() { return stop_time_; }
+  const base::Time& load_start_time() { return start_time_; }
+  const base::Time& load_stop_time() { return stop_time_; }
 
  private:
-  base::TimeTicks start_time_;
-  base::TimeTicks stop_time_;
+  base::Time start_time_;
+  base::Time stop_time_;
 
    DISALLOW_COPY_AND_ASSIGN(StatsCollectionObserver);
 };
diff --git a/tools/perf/metrics/histogram_util.py b/tools/perf/metrics/histogram_util.py
index 2d20998..8ee2fe0 100644
--- a/tools/perf/metrics/histogram_util.py
+++ b/tools/perf/metrics/histogram_util.py
@@ -81,3 +81,12 @@ def GetHistogramCount(histogram_type, histogram_name, tab):
     return histogram['count']
   else:
     return 0
+
+def GetHistogramSum(histogram_type, histogram_name, tab):
+  """Get the sum of events for the given histograms."""
+  histogram_json = GetHistogram(histogram_type, histogram_name, tab)
+  histogram = json.loads(histogram_json)
+  if 'sum' in histogram:
+    return histogram['sum']
+  else:
+    return 0
diff --git a/tools/perf/metrics/startup_metric.py b/tools/perf/metrics/startup_metric.py
index 1ebdbc3..4c36508 100644
--- a/tools/perf/metrics/startup_metric.py
+++ b/tools/perf/metrics/startup_metric.py
@@ -1,9 +1,11 @@
 # Copyright 2013 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.
+import collections
 import json
 
 from metrics import Metric
+from metrics import histogram_util
 
 
 class StartupMetric(Metric):
@@ -21,6 +23,73 @@ class StartupMetric(Metric):
   def Stop(self, page, tab):
     raise NotImplementedError()
 
+  def _GetBrowserMainEntryTime(self, tab):
+    """Returns the main entry time (in ms) of the browser."""
+    histogram_type = histogram_util.BROWSER_HISTOGRAM
+    high_bytes = histogram_util.GetHistogramSum(
+        histogram_type,
+        'Startup.BrowserMainEntryTimeAbsoluteHighWord',
+        tab)
+    low_bytes = histogram_util.GetHistogramSum(
+        histogram_type,
+        'Startup.BrowserMainEntryTimeAbsoluteLowWord',
+        tab)
+    if high_bytes == 0 and low_bytes == 0:
+      return None
+    return (int(high_bytes) << 32) | (int(low_bytes) << 1)
+
+  # pylint: disable=W0101
+  def _RecordTabLoadTimes(self, tab, browser_main_entry_time_ms, results):
+    """Records the tab load times for the browser. """
+    tab_load_times = []
+    TabLoadTime = collections.namedtuple(
+        'TabLoadTime',
+        ['load_start_ms', 'load_duration_ms', 'is_foreground_tab'])
+    num_open_tabs = len(tab.browser.tabs)
+    for i in xrange(num_open_tabs):
+      t = tab.browser.tabs[i]
+      t.WaitForDocumentReadyStateToBeComplete()
+      result = t.EvaluateJavaScript('statsCollectionController.tabLoadTiming()')
+      result = json.loads(result)
+
+      if 'load_start_ms' not in result or 'load_duration_ms' not in result:
+        raise Exception("Outdated Chrome version, "
+            "statsCollectionController.tabLoadTiming() not present")
+        return
+      if result['load_duration_ms'] is None:
+        tab_title = t.EvaluateJavaScript('document.title')
+        print "Page: ", tab_title, " didn't finish loading."
+        continue
+
+      is_foreground_tab = t.EvaluateJavaScript('!document.hidden')
+      tab_load_times.append(TabLoadTime(
+          int(result['load_start_ms']),
+          int(result['load_duration_ms']),
+          is_foreground_tab))
+
+    # Postprocess results
+    load_complete_times = (
+        [t.load_start_ms + t.load_duration_ms for t in tab_load_times])
+    load_complete_times.sort()
+
+    foreground_tab_stats = (
+        [t for t in tab_load_times if t.is_foreground_tab == True])
+    if (len(foreground_tab_stats) != 1):
+      raise Exception ("More than one foreground tab? ", foreground_tab_stats)
+    foreground_tab_stats = foreground_tab_stats[0]
+
+    # Report load stats.
+    foreground_tab_load_complete = ((foreground_tab_stats.load_start_ms +
+        foreground_tab_stats.load_duration_ms) - browser_main_entry_time_ms)
+
+    results.Add(
+        'foreground_tab_load_complete', 'ms', foreground_tab_load_complete)
+
+    if num_open_tabs > 1:
+      last_tab_load_complete = (
+          load_complete_times[-1] - browser_main_entry_time_ms)
+      results.Add('last_tab_load_complete', 'ms', last_tab_load_complete)
+
   def AddResults(self, tab, results):
     get_histogram_js = 'statsCollectionController.getBrowserHistogram("%s")'
 
@@ -38,3 +107,10 @@ class StartupMetric(Metric):
             (result['buckets'][0]['high'] + result['buckets'][0]['low']) / 2
 
       results.Add(display_name, 'ms', measured_time)
+
+    # Get tab load times.
+    browser_main_entry_time_ms = self._GetBrowserMainEntryTime(tab)
+    if (browser_main_entry_time_ms is None):
+      print "Outdated Chrome version, browser main entry time not supported."
+      return
+    self._RecordTabLoadTimes(tab, browser_main_entry_time_ms, results)