Detect perf regressions and speedups automatically....

log_parser/process_log.py

Index: log_parser/process_log.py
===================================================================
--- log_parser/process_log.py	(revision 24874)
+++ log_parser/process_log.py	(working copy)
@@ -19,6 +19,8 @@
 import chromium_config as config
 import chromium_utils
 
+from buildbot.status import builder
+
 READABLE_FILE_PERMISSIONS = int('644', 8)
 EXECUTABLE_FILE_PERMISSIONS = int('755', 8)
 
@@ -26,6 +28,38 @@
 # of graph names for use by the JS doing the plotting.
 GRAPH_LIST = config.Master.perf_graph_list
 
+# perf_expectations.json holds performance expectations.  It is a
+# JSON-formatted file with this format:
+#
+#   {PERFID: {
+#      RESULTTYPE: {"delta": DELTA, "var": VAR},
+#      RESULTTYPE: {"delta": DELTA, "var": VAR},
+#      ...
+#    },
+#    ...,
+#    "loaded": true
+#   }
+#
+# PERFID (string):
+#   Perf mapping identifier of the form "build-perf-name/test-name",
+#   (see factory/chromium_commands.py).
+#
+# RESULTTYPE (string):
+#   A particular trace within a test (ie. t, vm_rss_f_r).
+#
+# DELTA (integer):
+#   Delta tolerance (test - ref).
+#
+# VAR (integer):
+#   Variance tolerance.
+#
+# Notes:
+#   - Strings are quoted with " (not ').
+#   - Comments are not allowed in JSON.
+#
+PERF_EXPECTATIONS = ('../scripts/master/log_parser/perf_expectations/' +
+                     'perf_expectations.json')
+
 def FormatFloat(number):
   """Formats float with two decimal points."""
   if number:
@@ -73,7 +107,7 @@
 class PerformanceLogProcessor(object):
   """ Parent class for performance log parsers. """
 
-  def __init__(self, report_link=None, output_dir=None):
+  def __init__(self, report_link=None, output_dir=None, perf_name=None):
     self._report_link = report_link
     if output_dir is None:
       output_dir = os.getcwd()
@@ -82,9 +116,107 @@
     self._output_dir = output_dir
     self._matches = {}
 
+    # Performance regression/speedup alerts.
+    self._perf_name = perf_name
+    self._actual_performance = None
+    self._expected_performance = None
+    self._result_types = []
+    self._perf_regress = []
+    self._var_regress = []
+    self._perf_improve = []
+    self._var_improve = []
+
     # The revision isn't known until the Process() call.
     self._revision = -1
 
+  def LoadPerformanceExpectations(self):
+    self._expected = {}
+    try:
+      perf_file = open(PERF_EXPECTATIONS, 'r')
+    except IOError, e:
+      raise

[M-A Ruel, 2009/08/31 20:31:12]

That seems quite useless

+
+    perf_list = []
+    if perf_file:
+      try:
+        perf_list = simplejson.load(perf_file)
+      except ValueError:
+        perf_file.seek(0)
+        logging.error("Error parsing %s: '%s'" % (PERF_EXPECTATIONS,
+                      perf_file.read().strip()))

[M-A Ruel, 2009/08/31 20:31:12]

I'm not sure it's a good idea to read the file after the exception.

+      perf_file.close()
+
+    # Find this perf/test entry
+    if perf_list and perf_list.has_key(self._perf_name):
+        self._expected_performance = perf_list[self._perf_name]
+
+  def PerformanceChangesAsText(self):
+    text = []
+
+    if len(self._perf_regress) > 0:
+      text.append("PERF_REGRESS: " + ', '.join(self._perf_regress))
+
+    if len(self._var_regress) > 0:
+      text.append("VAR_REGRESS: " + ', '.join(self._var_regress))
+
+    if len(self._perf_improve) > 0:
+      text.append("PERF_IMPROVE: " + ', '.join(self._perf_improve))
+
+    if len(self._var_improve) > 0:
+      text.append("VAR_IMPROVE: " + ', '.join(self._var_improve))
+
+    return text
+
+  def PerformanceChanges(self):
+    # Load performance expectations for this test.
+    self.LoadPerformanceExpectations()
+
+    # Return if no performance expectations or results were found.
+    if not self._expected_performance or not self._actual_performance:
+      return []
+
+    # Compare actual and expected results.
+    for type in self._result_types:
+      if not (self._expected_performance.has_key(type) and
+              self._actual_performance.has_key(type)):
+        # Skip result types we don't know about.
+        continue
+
+      expect = self._expected_performance[type]
+      actual = self._actual_performance[type]
+
+      # Set the high and low performance and variance tolerances.  The actual
+      # delta and variance needs to be within 50% above and below this range to
+      # keep the performance test green.  If the results fall above or below
+      # this range, the test will go red (signaling a regression) or orange
+      # (signaling a speedup).
+      high_perf = (expect['delta'] + 1.5*expect['var'])
+      low_perf = (expect['delta'] - 1.5*expect['var'])
+      high_var = 1.5*expect['var']
+      low_var = 0.5*expect['var']
+
+      if actual['delta'] > high_perf:
+        self._perf_regress.append(type)
+      elif actual['delta'] < low_perf:
+        self._perf_improve.append(type)
+
+      if actual['var'] > high_var:
+        self._var_regress.append(type)
+      elif actual['var'] < low_var:
+        self._var_improve.append(type)
+
+    return self.PerformanceChangesAsText()
+
+  def evaluateCommand(self, cmd):
+    if len(self._perf_regress) > 0 or len(self._var_regress) > 0:
+      return builder.FAILURE
+
+    if len(self._perf_improve) > 0 or len(self._var_improve) > 0:
+      return builder.WARNINGS
+
+    # There was no change in performance, report success.
+    return builder.SUCCESS
+
   def Process(self, revision, data):
     """Invoked by the step with data from log file once it completes.
 
@@ -343,7 +475,7 @@
     self.__CreateSummaryOutput()
     if self._ShouldWriteResults():
       self.__SaveGraphInfo()
-    return self._text_summary
+    return self.PerformanceChanges() + self._text_summary
 
   def _ProcessLine(self, line):
     line_match = self.RESULTS_REGEX.match(line)
@@ -388,6 +520,43 @@
       graph.traces[trace_name] = trace
       self._graphs[graph_name] = graph
 
+      # Set actual performance data when we come across useful values.
+      #
+      # trace_name will be of the form "RESULTTYPE" or "RESULTTYPE_ref".
+      # A trace with _ref in its name refers to a reference build.
+      #
+      # Common result types for page cyclers: t, vm_rss_f_r, IO_b_b, etc.
+      # A test's result types vary between test types.  Currently, a test
+      # only needs to output the appropriate text format to embed a new
+      # result type.
+
+      m = re.match(r"^(\w+)_ref$", trace_name)
+      if m:
+        is_ref_build = True
+        result_type = m.group(1)
+      else:
+        is_ref_build = False
+        result_type = trace_name
+
+      if not self._actual_performance:
+        self._actual_performance = {}
+
+      if not self._actual_performance.has_key(result_type):
+        self._actual_performance[result_type] = {}
+
+      actual = self._actual_performance[result_type]
+      if is_ref_build:
+        actual['ref'] = trace.value
+      else:
+        actual['test'] = trace.value
+        actual['var'] = trace.stddev
+
+      # If we have both the test and ref results, compute the delta for this
+      # result type.
+      if actual.has_key('test') and actual.has_key('ref'):
+        self._result_types.append(result_type)
+        actual['delta'] = actual['test'] - actual['ref']
+
   def _CalculateStatistics(self, value_list, trace_name):
     """Returns a tuple (mean, standard deviation) from a list of values.