Detect perf regressions and speedups automatically....

log_parser/process_log.py

 #!/usr/bin/python
 # Copyright (c) 2006-2008 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.
 
 """Defines various log processors used by buildbot steps.
 
 Current approach is to set an instance of log processor in
 the ProcessLogTestStep implementation and it will call process()
 method upon completion with full data from process stdio.
 """
 
 import errno
 import logging
 import os
 import re
 import simplejson
 
 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)
 
 # For the GraphingLogProcessor, the file into which it will save a list
 # 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:
     return '%.2f' % number
   else:
     return '0.00'
 
 
 def Prepend(filename, data):
   chromium_utils.Prepend(filename, data)
@@ skipping 27 matching lines @@
   if digits >= 100:
     # Don't append a meaningless '.0' to an integer number.
     digits = int(digits)
   # Exponent is now divisible by 3, between -3 and 6 inclusive: (-3, 0, 3, 6).
   return '%s%s' % (digits, METRIC_SUFFIX[exponent])
 
 
 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()
     elif output_dir.startswith('~'):
       output_dir = os.path.expanduser(output_dir)
     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.
 
     Each subclass needs to override this method to provide custom logic,
     which should include setting self._revision.
     Args:
       revision: changeset revision number that triggered the build.
       data: content of the log file that needs to be processed.
 
     Returns:
@@ skipping 238 matching lines @@
 
     self._MakeOutputDirectory()
 
     # Parse the log and fill _graphs.
     for log_line in data.splitlines():
       self._ProcessLine(log_line)
 
     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)
     if line_match:
       match_dict = line_match.groupdict()
       graph_name = match_dict['GRAPH'].strip()
       trace_name = match_dict['TRACE'].strip()
 
       graph = self._graphs.get(graph_name, Graph())
       graph.units = match_dict['UNITS'] or ''
@@ skipping 24 matching lines @@
       else:
         try:
           trace.value = float(trace.value)
         except ValueError:
           logging.warning("Bad test output: '%s'" % trace.value.strip())
           return
 
       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.
 
     This method may be overridden by subclasses wanting a different standard
     deviation calcuation (or some other sort of error value entirely).
 
     Args:
       value_list: the list of values to use in the calculation
       trace_name: the trace that produced the data (not used in the base
           implementation, but subclasses may use it)
@@ skipping 181 matching lines @@
            FormatFloat(mean),
            FormatFloat(stddev),
            self._JoinWithSpacesAndNewLine(times)))
 
     filename = os.path.join(self._output_dir,
                             '%s_%s.dat' % (self._revision, trace_name))
     file = open(filename, 'w')
     file.write(''.join(file_data))
     file.close()
     os.chmod(filename, READABLE_FILE_PERMISSIONS)