Pyauto performance tests now output data to be graphed using autotest.

chrome/test/functional/perf.py

 #!/usr/bin/python
 # Copyright (c) 2011 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|.
 That value can optionally be tweaked by setting an environment variable
 'NUM_ITERATIONS' to a positive integer, representing the number of iterations
 to run.
 """
 
 import logging
 import math
 import os
 import time
 
 import pyauto_functional  # Must be imported before pyauto.
 import pyauto
 
 
 class PerfTest(pyauto.PyUITest):
   """Basic performance tests."""
 
   _DEFAULT_NUM_ITERATIONS = 50
+  _PERF_OUTPUT_MARKER_PRE = '_PERF_PRE_'
+  _PERF_OUTPUT_MARKER_POST = '_PERF_POST_'
 
   def setUp(self):
     """Performs necessary setup work before running each test."""
     self._num_iterations = self._DEFAULT_NUM_ITERATIONS
     if 'NUM_ITERATIONS' in os.environ:
       try:
         self._num_iterations = int(os.environ['NUM_ITERATIONS'])
         if self._num_iterations <= 0:
           raise ValueError('Environment variable NUM_ITERATIONS must be an '
                            'integer > 0.')
       except ValueError, e:
         self.fail('Error processing environment variable: %s' % e)
     pyauto.PyUITest.setUp(self)
 
   def _MeasureElapsedTime(self, python_command, num_invocations):

[truty, 2011/08/25 04:25:01]

Are you considering that it would make this more reusable to separate the common
utility functions here into a base PerfTest class and then to specialize that
class with say a TabPerfTest class with the actual test code below?

[dennis_jeffrey, 2011/08/25 22:33:05]

I think this is a great idea, and would like to do it.  But I'd like to address
it in a subsequent CL if you don't mind, since it involves restructuring the
code here, and it strays a bit from the point of the current CL.  I added a TODO
for that to make sure I don't forget about it.  I'd like to take care of it in a
later "cleanup" CL that involves reorganizing this code.

     """Measures time (in msec) to execute a python command one or more times.
 
     Args:
       python_command: A callable.
       num_invocations: An integer number of times to invoke the given command.
 
     Returns:
       The time required to execute the python command the specified number of
       times, in milliseconds as a float.
     """
     assert callable(python_command)
     start_time = time.time()
     for _ in range(num_invocations):
       python_command()
     stop_time = time.time()
     return (stop_time - start_time) * 1000  # Convert to milliseconds.

[truty, 2011/08/25 04:25:01]

Just wondering...why not use timeit?  There are issues such as GC that can
affect pure Python timings discussed in timeit.

[dennis_jeffrey, 2011/08/25 22:33:05]

I didn't use it because I didn't know about it - that's awesome!

 
   def _AvgAndStdDev(self, values):
     """Computes the average and standard deviation of a set of values.
 
     Args:
       values: A list of numeric values.
 
     Returns:
       A 2-tuple of floats (average, standard_deviation).
     """
     avg = float(sum(values)) / len(values)
     temp_vals = [math.pow(x - avg, 2) for x in values]
     std_dev = math.sqrt(sum(temp_vals) / len(temp_vals))

[truty, 2011/08/25 04:25:01]

This illustrates why I use a Python stats lib instead of writing these.  I think
you want to float() the len(temp_vals) otherwise this could end up being int
division which would incur unexpected rounding.  Also, you're calculating the
population stddev opposed to sample and I think sample is the more common
approach.

[dennis_jeffrey, 2011/08/25 22:33:05]

Originally Nirnimesh had recommended I use the "numpy" module for computing
avg/std dev, but we found out that it's a third-party library that we could not
always count on to be present on all the platforms (e.g., it seemed to exist on
Linux and not Windows).  Since we'd like these perf tests to also run on chrome
on Windows, we decided to leave it like this.

That is a great point about being careful of integer division unexpectedly
cropping up.  However, I think it shouldn't happen here, unless I'm missing
something (in which case I'd like to hear where I'm wrong!).  The reason is that
the division at line 74 above depends upon "sum(temp_vals)", which itself is the
sum of a set of list elements computed at line 73.  Each list element is
computed by squaring a value 'x - avg', with 'avg' being computed at line 72. 
'avg' should be a float because it is computed using "float(sum(values))".  This
should mean that the expression 'x - avg' should also be a float, making its
square a float, making each element of the "temp_vals" list a float, making
"sum(temp_vals)" in line 74 a float, preventing integer division at that line. 
I could be wrong here, so please let me know if I am - I just wanted to check to
make sure I understand this properly.

You're right about the population vs. sample std dev point you bring up.  I was
reading a bit about the different types of std dev, and I see that "sample" is
more commonly-used (according to wikipedia).  The reason I originally went with
"population" was because I figured I just want the std dev of the given set of
measurements, which seems to form the "complete population" (but I am not sure
whether that reasoning is correct).  But a benefit of using "sample" is that the
standard deviation value would be larger, which seems like a more conservative
value to report.  Do you recommend that I change it to "sample"?

[truty, 2011/08/26 20:33:00]

-I use a Python stats library that is opensource - we should discuss it this
week.
-You're right about the float.  I'm just paranoid I guess - sorry.
-I prefer the sample stddev - please check with jrbarnette for a final
preference though.

[dennis_jeffrey, 2011/08/26 23:23:54]

I changed the computation to "sample" std dev based on suggestion by jrbarnette.

     return avg, std_dev
 
-  def _PrintSummaryResults(self, first_val, units, values=[]):
+  def _OutputPerfGraphValue(self, description, value):
+    """Outputs a performance value to have it graphed on the performance bots.
+
+    Only used for ChromeOS.
+
+    Args:
+      description: A string description of the performance value.
+      value: A numeric value representing a single performance measurement.
+    """
+    if self.IsChromeOS():
+      print '%s(\'%s\', %.2f)%s' % (self._PERF_OUTPUT_MARKER_PRE, description,
+                                    value, self._PERF_OUTPUT_MARKER_POST)
+
+  def _PrintSummaryResults(self, description, first_val, units, values=[]):
     """Logs summary measurement information.
 
     Args:
+      description: A string description for the specified results.
       first_val: A numeric measurement value for a single initial trial.
       units: A string specifying the units for the specified measurements.
       values: A list of numeric value measurements.
     """
+    logging.info('Results for: ' + description)
     logging.debug('Single trial: %.2f %s', first_val, units)
     if values:
       avg, std_dev = self._AvgAndStdDev(values)
       logging.info('Number of iterations: %d', len(values))
       for val in values:
         logging.info('  %.2f %s', val, units)
       logging.info('  --------------------------')
       logging.info('  Average: %.2f %s', avg, units)
       logging.info('  Std dev: %.2f %s', std_dev, units)
+      self._OutputPerfGraphValue('%s_%s' % (units, description), avg)

[truty, 2011/08/25 04:25:01]

FYI, it's typical for current ChromeOS perf tests to write all the keyvals to
the Autotest db.  That way the data is preserved in case a stat function is
later proven improper.

[dennis_jeffrey, 2011/08/25 22:33:05]

Is this something that happens automatically when values are written to the
'keyval' file using write_perf_keyval()?  I saw a comment in
platform_BootPerf.py saying that "Keyval attribute names go into a database that
truncates after 30 characters", implying that those results are going into the
database, but I don't see any code there that explicitly does that.

[truty, 2011/08/26 20:33:00]

Yes. Using write_perf_keyval() causes the entire dict to get written to the db.

+    else:
+      self._OutputPerfGraphValue('%s_%s' % (units, description), first_val)
 
-  def _RunNewTabTest(self, open_tab_command, num_tabs=1):
+  def _RunNewTabTest(self, description, open_tab_command, num_tabs=1):
     """Runs a perf test that involves opening new tab(s).
 
     This helper function can be called from different tests to do perf testing
     with different types of tabs.  It is assumed that the |open_tab_command|
     will open up a single tab.

[truty, 2011/08/25 04:25:01]

I think you should explain this pattern of separating the initial sample from
the remaining iterations.  It's ambiguous what 1 iteration would mean - since
iterations=1 would actually return 2 separate samples.

[dennis_jeffrey, 2011/08/25 22:33:05]

This is indeed something that was bugging me a little - actually I think I'd
like to remove the code that does the initial sample, since I'm not using it for
anything right now.  That way, the number of iterations specified would exactly
match the number of samples actually taken.  I added a TODO to take care of this
when I clean up the organization of this file.

 
     Args:
+      description: A string description of the associated tab test.
       open_tab_command: A callable that will open a single tab.
       num_tabs: The number of tabs to open, i.e., the number of times to invoke
                 the |open_tab_command|.
     """
     assert callable(open_tab_command)
     orig_elapsed = self._MeasureElapsedTime(open_tab_command, num_tabs)
     self.assertEqual(1 + num_tabs, self.GetTabCount(),
                      msg='Did not open %d new tab(s).' % num_tabs)
     for _ in range(num_tabs):
       self.GetBrowserWindow(0).GetTab(1).Close(True)
 
     timings = []
     for _ in range(self._num_iterations):
       elapsed = self._MeasureElapsedTime(open_tab_command, num_tabs)
       self.assertEqual(1 + num_tabs, self.GetTabCount(),
                        msg='Did not open %d new tab(s).' % num_tabs)
       for _ in range(num_tabs):
         self.GetBrowserWindow(0).GetTab(1).Close(True)
       timings.append(elapsed)
 
-    self._PrintSummaryResults(orig_elapsed, 'ms', values=timings)
+    self._PrintSummaryResults(description, orig_elapsed, 'milliseconds',
+                              values=timings)
 
   def testNewTab(self):
     """Measures time to open a new tab."""
-    self._RunNewTabTest(lambda: self.AppendTab(pyauto.GURL('chrome://newtab')))
+    self._RunNewTabTest('NewTabPage',
+                        lambda: self.AppendTab(pyauto.GURL('chrome://newtab')))
 
   def testNewTabPdf(self):
     """Measures time to open a new tab navigated to a PDF file."""
     url = self.GetFileURLForDataPath('pyauto_private', 'pdf', 'TechCrunch.pdf')
-    self._RunNewTabTest(lambda: self.AppendTab(pyauto.GURL(url)))
+    self._RunNewTabTest('NewTabPdfPage',
+                        lambda: self.AppendTab(pyauto.GURL(url)))
 
   def testNewTabFlash(self):
     """Measures time to open a new tab navigated to a flash page."""
     url = self.GetFileURLForDataPath('plugin', 'flash.swf')
-    self._RunNewTabTest(lambda: self.AppendTab(pyauto.GURL(url)))
+    self._RunNewTabTest('NewTabFlashPage',
+                        lambda: self.AppendTab(pyauto.GURL(url)))
 
   def test20Tabs(self):
     """Measures time to open 20 tabs."""
     self._RunNewTabTest(
+        '20TabsNewTabPage',
         lambda: self.AppendTab(pyauto.GURL('chrome://newtab')), num_tabs=20)
 
   def testV8BenchmarkSuite(self):
     """Measures score from online v8 benchmark suite."""
     url = self.GetFileURLForDataPath('v8_benchmark_v6', 'run.html')
     self.AppendTab(pyauto.GURL(url))
     js = """
         var val = document.getElementById("status").innerHTML;
         window.domAutomationController.send(val);
     """
     self.assertTrue(
         self.WaitUntil(
             lambda: 'Score:' in self.ExecuteJavascript(js, 0, 1), timeout=300,
             expect_retval=True),
         msg='Timed out when waiting for v8 benchmark score.')
     val = self.ExecuteJavascript(js, 0, 1)
     score = int(val[val.find(':') + 2:])
-    self._PrintSummaryResults(score, 'score')
+    self._PrintSummaryResults('V8Benchmark', score, 'score')
 
 
 if __name__ == '__main__':
   pyauto_functional.Main()