Refactor/rewrite scroll.js, reporting results as renderingStats objects.

chrome/test/functional/perf.py

 #!/usr/bin/env python
 # Copyright (c) 2012 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.
 
 """Basic pyauto performance tests.
 
 For tests that need to be run for multiple iterations (e.g., so that average
 and standard deviation values can be reported), the default number of iterations
 run for each of these tests is specified by |_DEFAULT_NUM_ITERATIONS|.
@@ skipping 568 matching lines @@
     timings = []
     for iteration in range(self._num_iterations + 1):
       orig_timeout_count = self._timeout_count
       elapsed_time = self._MeasureElapsedTime(open_tab_command,
                                               num_invocations=num_tabs)
       # Only count the timing measurement if no automation call timed out.
       if self._timeout_count == orig_timeout_count:
         # Ignore the first iteration.
         if iteration:
           timings.append(elapsed_time)
-          logging.info('Iteration %d of %d: %f milliseconds', iteration,
+          logging.info('Iteration %d of %d: %f milliseconds', iteration + 1,

[dennis_jeffrey, 2012/08/16 17:50:59]

What is the reason for adding the "+1" to each of these logging messages?  I
believe the original code already outputs (by default)

Iteration 1 of 10
Iteration 2 of 10
...
Iteration 10 of 10

This is because when 10 iterations are needed, it actually does 11 iterations
and ignores the first one.

With the change in this line, I think it would output:

Iteration 2 of 10
Iteration 3 of 10
...
Iteration 11 of 10

[dtu, 2012/08/16 19:12:39]

Done. Sorry, you're right. The only loop that was missing the " + 1" was the one
in test2012Q3, since it doesn't skip the first iteration.

                        self._num_iterations, elapsed_time)
       self.assertTrue(self._timeout_count <= self._max_timeout_count,
                       msg='Test exceeded automation timeout threshold.')
       self.assertEqual(1 + num_tabs, self.GetTabCount(),
                        msg='Did not open %d new tab(s).' % num_tabs)
       for _ in range(num_tabs):
         self.CloseTab(tab_index=1)
 
     self._PrintSummaryResults(description, timings, 'milliseconds', graph_name)
 
@@ skipping 141 matching lines @@
       self.CloseTab(tab_index=1)
       return result_dict
 
     timings = {}
     for iteration in xrange(self._num_iterations + 1):
       result_dict = _RunBenchmarkOnce(url)
       # Ignore the first iteration.
       if iteration:
         for key, val in result_dict.items():
           timings.setdefault(key, []).append(val)
-        logging.info('Iteration %d of %d:\n%s', iteration, self._num_iterations,
-                     self.pformat(result_dict))
+        logging.info('Iteration %d of %d:\n%s', iteration + 1,
+                     self._num_iterations, self.pformat(result_dict))
 
     for key, val in timings.items():
       if key == 'final_score':
         self._PrintSummaryResults('V8Benchmark', val, 'score',
                                   'v8_benchmark_final')
       else:
         self._PrintSummaryResults('V8Benchmark-%s' % key, val, 'score',
                                   'v8_benchmark_individual')
 
   def testSunSpider(self):
@@ skipping 807 matching lines @@
       self.DownloadAndWaitForStart(url)
       self.WaitForAllDownloadsToComplete(timeout=2 * 60 * 1000)  # 2 minutes.
 
     timings = []
     for iteration in range(self._num_iterations + 1):
       elapsed_time = self._MeasureElapsedTime(
           lambda: _DownloadFile(DOWNLOAD_100MB_URL), num_invocations=1)
       # Ignore the first iteration.
       if iteration:
         timings.append(elapsed_time)
-        logging.info('Iteration %d of %d: %f milliseconds', iteration,
+        logging.info('Iteration %d of %d: %f milliseconds', iteration + 1,
                      self._num_iterations, elapsed_time)
       self.SetDownloadShelfVisible(False)
       _CleanupAdditionalFilesInDir(download_dir, orig_downloads)
 
     self._PrintSummaryResults('Download100MBFile', timings, 'milliseconds',
                               'download_file')
 
     # Tell the local server to delete the 100 MB file.
     self.NavigateToURL(DELETE_100MB_URL)
 
@@ skipping 23 matching lines @@
           self.WaitUntil(_IsUploadComplete, timeout=120, expect_retval=True,
                          retry_sleep=0.10),
           msg='Upload failed to complete before the timeout was hit.')
 
     timings = []
     for iteration in range(self._num_iterations + 1):
       elapsed_time = self._MeasureElapsedTime(_RunSingleUpload)
       # Ignore the first iteration.
       if iteration:
         timings.append(elapsed_time)
-        logging.info('Iteration %d of %d: %f milliseconds', iteration,
+        logging.info('Iteration %d of %d: %f milliseconds', iteration + 1,
                      self._num_iterations, elapsed_time)
 
     self._PrintSummaryResults('Upload50MBFile', timings, 'milliseconds',
                               'upload_file')
 
 
-class FrameTimes(object):
-  """Container for a list of frame times."""
-
-  def __init__(self, frame_times):
-    self._frame_times = frame_times
-
-  def GetFps(self):
-    if not self._frame_times:
-      return 0
-    avg = sum(self._frame_times) / len(self._frame_times)
-    if not avg:
-      return 0
-    return int(1000.0 / avg)
-
-  def GetMeanFrameTime(self):
-    return Mean(self._frame_times)
-
-  def GetPercentBelow60Fps(self):
-    if not self._frame_times:
-      return 0
-    threshold = math.ceil(1000 / 60.)
-    num_frames_below_60 = len([t for t in self._frame_times if t > threshold])
-    num_frames = len(self._frame_times)
-    return (100. * num_frames_below_60) / num_frames
-
-
 class ScrollResults(object):
   """Container for ScrollTest results."""
 
-  def __init__(self, first_paint_seconds, frame_times_lists):
-    assert len(frame_times_lists) == 2, 'Expecting initial and repeat times'
-    self.first_paint_time = 1000.0 * first_paint_seconds
-    self.initial_frame_times = FrameTimes(frame_times_lists[0])
-    self.repeat_frame_times = FrameTimes(frame_times_lists[1])
+  def __init__(self, first_paint_seconds, results_list):
+    assert len(results_list) == 2, 'Expecting initial and repeat results.'
+    self._first_paint_time = 1000.0 * first_paint_seconds
+    self._results_list = results_list
+
+  def GetFirstPaintTime(self):
+    return self._first_paint_time
+
+  def GetFrameCount(self, index):
+    results = self._results_list[index]
+    return results.get('numFramesSentToScreen', results['numAnimationFrames'])
+
+  def GetFps(self, index):
+    return (self.GetFrameCount(index) /
+            self._results_list[index]['totalTimeInSeconds'])
+
+  def GetMeanFrameTime(self, index):
+    return (self._results_list[index]['totalTimeInSeconds'] /
+            self.GetFrameCount(index))
+
+  def GetPercentBelow60Fps(self, index):
+    return (float(self._results_list[index]['droppedFrameCount']) /
+            self.GetFrameCount(index))
 
 
 class BaseScrollTest(BasePerfTest):
   """Base class for tests measuring scrolling performance."""
 
   def setUp(self):
     """Performs necessary setup work before running each test."""
     super(BaseScrollTest, self).setUp()
     scroll_file = os.path.join(self.DataDir(), 'scroll', 'scroll.js')
     with open(scroll_file) as f:
       self._scroll_text = f.read()
 
-  def RunSingleInvocation(self, url, setup_js=''):
+  def ExtraChromeFlags(self):
+    """Ensures Chrome is launched with custom flags.
+
+    Returns:
+      A list of extra flags to pass to Chrome when it is launched.
+    """
+    # Extra flag used by scroll performance tests.
+    return (super(BaseScrollTest, self).ExtraChromeFlags() +
+            ['--enable-gpu-benchmarking'])
+
+  def RunSingleInvocation(self, url, is_gmail_test=False):
     """Runs a single invocation of the scroll test.
 
     Args:
       url: The string url for the webpage on which to run the scroll test.
-      setup_js: String representing additional Javascript setup code to execute
-          in the webpage immediately before running the scroll test.
+      is_gmail_test: True iff the test is a GMail test.
 
     Returns:
       Instance of ScrollResults.
     """
+
     self.assertTrue(self.AppendTab(pyauto.GURL(url)),
                     msg='Failed to append tab for webpage.')
 
-    js = """
-        %s
-        %s
-        __scroll_test();
-        window.domAutomationController.send('done');
-    """ % (self._scroll_text, setup_js)
-    self.ExecuteJavascript(js, tab_index=1)
+    timeout = pyauto.PyUITest.ActionTimeoutChanger(self, 300 * 1000)  # ms
+    test_js = """%s;
+        var __stringify = JSON.stringify || JSON.encode;
+        __scrollTest(function(results) {
+          window.domAutomationController.send(__stringify(results));
+        }, %s);
+    """ % (self._scroll_text, 'true' if is_gmail_test else 'false')
+    results = simplejson.loads(self.ExecuteJavascript(test_js, tab_index=1))
 
-    # Poll the webpage until the test is complete.
-    def IsTestComplete():
-      done_js = """
-        if (__scrolling_complete)
-          window.domAutomationController.send('complete');
-        else
-          window.domAutomationController.send('incomplete');
-      """
-      return self.ExecuteJavascript(done_js, tab_index=1) == 'complete'
+    first_paint_js = ('window.domAutomationController.send('
+                      '(chrome.loadTimes().firstPaintTime - '
+                      'chrome.loadTimes().requestTime).toString());')
+    first_paint_time = float(self.ExecuteJavascript(first_paint_js,
+                                                    tab_index=1))
 
-    self.assertTrue(
-        self.WaitUntil(IsTestComplete, timeout=300, expect_retval=True,
-                       retry_sleep=1),
-        msg='Timed out when waiting for scrolling tests to complete.')
+    self.CloseTab(tab_index=1)
 
-    # Get the scroll test results from the webpage.
-    results_js = """
-      var __stringify = JSON.stringify || JSON.encode;
-      window.domAutomationController.send(__stringify({
-          'first_paint_time': chrome.loadTimes().firstPaintTime -
-                              chrome.loadTimes().requestTime,
-          'frame_times': __frame_times,
-      }));
-    """
-    results = eval(self.ExecuteJavascript(results_js, tab_index=1))
-    self.CloseTab(tab_index=1)
-    return ScrollResults(results['first_paint_time'], results['frame_times'])
+    return ScrollResults(first_paint_time, results)
 
-  def RunScrollTest(self, url, description, graph_name, setup_js=''):
+  def RunScrollTest(self, url, description, graph_name, is_gmail_test=False):
     """Runs a scroll performance test on the specified webpage.
 
     Args:
       url: The string url for the webpage on which to run the scroll test.
       description: A string description for the particular test being run.
       graph_name: A string name for the performance graph associated with this
           test.  Only used on Chrome desktop.
-      setup_js: String representing additional Javascript setup code to execute
-          in the webpage immediately before running the scroll test.
+      is_gmail_test: True iff the test is a GMail test.
     """
     results = []
     for iteration in range(self._num_iterations + 1):
-      result = self.RunSingleInvocation(url, setup_js)
+      result = self.RunSingleInvocation(url, is_gmail_test)
       # Ignore the first iteration.
       if iteration:
-        fps = result.repeat_frame_times.GetFps()
+        fps = result.GetFps(1)
         assert fps, '%s did not scroll' % url
-        logging.info('Iteration %d of %d: %f fps', iteration,
+        logging.info('Iteration %d of %d: %f fps', iteration + 1,
                      self._num_iterations, fps)
         results.append(result)
     self._PrintSummaryResults(
-        description, [r.repeat_frame_times.GetFps() for r in results],
+        description, [r.GetFps(1) for r in results],
         'FPS', graph_name)
 
 
 class PopularSitesScrollTest(BaseScrollTest):
   """Measures scrolling performance on recorded versions of popular sites."""
 
   def ExtraChromeFlags(self):
     """Ensures Chrome is launched with custom flags.
 
     Returns:
       A list of extra flags to pass to Chrome when it is launched.
     """
     return super(PopularSitesScrollTest,
                  self).ExtraChromeFlags() + PageCyclerReplay.CHROME_FLAGS
 
   def _GetUrlList(self, test_name):
     """Returns list of recorded sites."""
     sites_path = PageCyclerReplay.Path('page_sets', test_name=test_name)
     with open(sites_path) as f:
       sites_text = f.read()
     js = """
       %s
       window.domAutomationController.send(JSON.stringify(pageSets));
     """ % sites_text
     page_sets = eval(self.ExecuteJavascript(js))
     return list(itertools.chain(*page_sets))[1:]  # Skip first.
 
   def _PrintScrollResults(self, results):
     self._PrintSummaryResults(
-        'initial', [r.initial_frame_times.GetMeanFrameTime() for r in results],
+        'initial', [r.GetMeanFrameTime(0) for r in results],
         'ms', 'FrameTimes')
     self._PrintSummaryResults(
-        'repeat', [r.repeat_frame_times.GetMeanFrameTime() for r in results],
+        'repeat', [r.GetMeanFrameTime(1) for r in results],
         'ms', 'FrameTimes')
     self._PrintSummaryResults(
         'initial',
-        [r.initial_frame_times.GetPercentBelow60Fps() for r in results],
+        [r.GetPercentBelow60Fps(0) for r in results],
         'percent', 'PercentBelow60FPS')
     self._PrintSummaryResults(
         'repeat',
-        [r.repeat_frame_times.GetPercentBelow60Fps() for r in results],
+        [r.GetPercentBelow60Fps(1) for r in results],
         'percent', 'PercentBelow60FPS')
     self._PrintSummaryResults(
-        'first_paint_time', [r.first_paint_time for r in results],
+        'first_paint_time', [r.GetFirstPaintTime() for r in results],
         'ms', 'FirstPaintTime')
 
   def test2012Q3(self):
     test_name = '2012Q3'
     urls = self._GetUrlList(test_name)
     results = []
     with PageCyclerReplay.ReplayServer(test_name) as replay_server:
       if replay_server.is_record_mode:
         self._num_iterations = 1
       for iteration in range(self._num_iterations):
         for url in urls:
           result = self.RunSingleInvocation(url)
-          fps = result.initial_frame_times.GetFps()
+          fps = result.GetFps(0)
           assert fps, '%s did not scroll' % url
-          logging.info('Iteration %d of %d: %f fps', iteration,
+          logging.info('Iteration %d of %d: %f fps', iteration + 1,
                        self._num_iterations, fps)
           results.append(result)
     self._PrintScrollResults(results)
 
 
 class ScrollTest(BaseScrollTest):
   """Tests to measure scrolling performance."""
 
   def ExtraChromeFlags(self):
     """Ensures Chrome is launched with custom flags.
@@ skipping 18 matching lines @@
 
   def testGooglePlusScroll(self):
     """Runs the scroll test on a Google Plus anonymized page."""
     self.RunScrollTest(
         self.GetFileURLForDataPath('scroll', 'plus.html'),
         'ScrollGooglePlusPage', 'scroll_fps')
 
   def testGmailScroll(self):
     """Runs the scroll test using the live Gmail site."""
     self._LoginToGoogleAccount(account_key='test_google_account_gmail')
-    self.RunScrollTest('http://www.gmail.com', 'ScrollGmail', 'scroll_fps',
-                       setup_js='__is_gmail_test = true;')
+    self.RunScrollTest('http://www.gmail.com', 'ScrollGmail',
+                       'scroll_fps', True)
 
 
 class FlashTest(BasePerfTest):
   """Tests to measure flash performance."""
 
   def _RunFlashTestForAverageFPS(self, webpage_url, description, graph_name):
     """Runs a single flash test that measures an average FPS value.
 
     Args:
       webpage_url: The string URL to a webpage that will run the test.
@@ skipping 356 matching lines @@
       'start_page': 'src/tools/page_cycler/webpagereplay/start.html',
       'extension':  'src/tools/page_cycler/webpagereplay/extension',
       }
 
   CHROME_FLAGS = webpagereplay.CHROME_FLAGS + [
       '--log-level=0',
       '--disable-background-networking',
       '--enable-experimental-extension-apis',
       '--enable-logging',
       '--enable-benchmarking',
+      '--enable-stats-table',

[dennis_jeffrey, 2012/08/16 17:50:59]

This was removed here:

https://chromiumcodereview.appspot.com/10829259/diff/1/chrome/test/functional...

What do we get from adding it back in?

[dtu, 2012/08/16 19:12:39]

Oh, interesting.

The reason is, when you have --enable-benchmarking, Chrome DCHECKs for
--enable-stats-table, so it'll crash with a Debug build:
http://code.google.com/searchframe#OAMlx_jo-ck/src/chrome/browser/chrome_cont...

Do these tests even use --enable-benchmarking? A comment on the bug from your
linked CL says it's not used:
http://code.google.com/p/chromium/issues/detail?id=133069#c16

In that case they can both be removed.

[slamm_google, 2012/08/16 19:33:52]

I was mistaken about --enable-benchmarking not being used.
The test does not use stats from it, however, the API is used to clear browser
data.

[dennis_jeffrey, 2012/08/16 21:00:36]

So if we remove --enable-stats-table, then we'll hit a DCHECK on debug builds. 
But if we add it back in, then the issue mentioned here would likely crop up
again:

http://code.google.com/p/chromium/issues/detail?id=133069#c19

Not sure what the best solution is here, but some options mentioned by slamm@:

(1) do not add the flag, and turn this test off for debug builds, since anyway
the test would run a lot more slowly on debug builds

(2) add this flag, but only when running with a debug build

(3) see if --enable-stats-table is really needed by --enable-benchmarking, and
doing some cleanup around that if possible.

       '--metrics-recording-only',
       '--activate-on-launch',
       '--no-first-run',
       '--no-proxy-server',
       ]
 
   @classmethod
   def Path(cls, key, **kwargs):
     return FormatChromePath(cls._PATHS[key], **kwargs)
 
@@ skipping 376 matching lines @@
     """Identifies the port number to which the server is currently bound.
 
     Returns:
       The numeric port number to which the server is currently bound.
     """
     return self._server.server_address[1]
 
 
 if __name__ == '__main__':
   pyauto_functional.Main()