Add option to command tester for running a test multiple times. Use that

tools/command_tester.py

 #!/usr/bin/python
 # Copyright (c) 2011 The Native Client Authors. All rights reserved.
 # Use of this source code is governed by a BSD-style license that can be
 # found in the LICENSE file.
 
 
 """Simple testing harness for running commands and checking expected output.
 
 This harness is used instead of shell scripts to ensure windows compatibility
 
@@ skipping 87 matching lines @@
 
       # This option must be '1' for the output to be captured, for checking
       # against golden files, special exit_status signals, etc.
       # When this option is '0', stdout and stderr will be streamed out.
       'capture_output': '1',
 
       'filter_regex': None,
       'filter_inverse': False,
       'filter_group_only': False,
 
-      # Script for processing output along with its arguments.
-      'process_output': '',
+      # Number of times a test is run.
+      # This is useful for getting multiple samples for time perf tests.
+      'num_runs': '1',

[Nick Bray, 2011/11/07 23:39:09]

Make this an integer.  The option parser will do the right thing and you can
remove all the int() casts.

If you're feeling agressive, you can fix capture_output, too, although I'd
rather that was in a separate CL.

[jvoung - send to chromium..., 2011/11/09 00:50:54]

Done. Leaving capture_output, track_cmdtime, alone for now.

+
+      # Scripts for processing output along with its arguments.
+      # This script is given the output of a single run.
+      'process_output_single': '',
+      # This script is given the concatenated output of all |num_runs|, after
+      # having been filtered by |process_output_single| for individual runs.
+      'process_output_combined': '',
 
       'time_warning': 0,
       'time_error': 0,
 
       'run_under': None,
   }
 
 def StringifyList(lst):
   return ','.join(lst)
 
 def DestringifyList(lst):
   # BUG(robertm): , is a legitimate character for an environment variable
   # value.
   return lst.split(',')
 
 # The following messages match gtest's formatting.  This improves log
 # greppability for people who primarily work on Chrome.  It also allows
 # gtest-specific hooks on the buildbots to fire.
 # The buildbots expect test names in the format "suite_name.test_name", so we
 # prefix the test name with a bogus suite name (nacl).
 def RunMessage():
-  return '[ RUN      ] nacl.%s' % GlobalSettings['name']
+  num_runs = int(GlobalSettings['num_runs'])
+  if num_runs > 1:
+    run_message_extra = '  (run %d times)' % num_runs
+  else:
+    run_message_extra = ''
+  return '[ RUN      ] nacl.%s%s' % (GlobalSettings['name'], run_message_extra)

[Nick Bray, 2011/11/07 23:39:09]

It might be clearer to produce the base string and then append to it?

[jvoung - send to chromium..., 2011/11/09 00:50:54]

Done.

 
 def FailureMessage(total_time):
   return '[  FAILED  ] nacl.%s (%d ms)' % (GlobalSettings['name'],
                                            total_time * 1000.0)
 
 def SuccessMessage(total_time):
   return '[       OK ] nacl.%s (%d ms)' % (GlobalSettings['name'],
                                            total_time * 1000.0)
 
 def LogPerfResult(graph_name, trace_name, value, units):
@@ skipping 110 matching lines @@
   except getopt.GetoptError, err:
     Print(str(err))  # will print something like 'option -a not recognized'
     sys.exit(-1)
 
   for o, a in opts:
     # strip the leading '--'
     option = o[2:]
     assert option in GlobalSettings
     if option == 'exit_status':
       GlobalSettings[option] = a
     elif type(GlobalSettings[option]) == int:

[Nick Bray, 2011/11/07 23:39:09]

Check this out!

[jvoung - send to chromium..., 2011/11/09 00:50:54]

Done =P

       GlobalSettings[option] = int(a)
     else:
       GlobalSettings[option] = a
 
   if (sys.platform == 'win32') and (GlobalSettings['subarch'] == '64'):
     GlobalPlatform = 'win64'
   else:
     GlobalPlatform = sys.platform
 
   # return the unprocessed options, i.e. the command
@@ skipping 30 matching lines @@
         words[0] == 'qemu:' and words[1] == 'uncaught' and
         words[2] == 'target' and words[3] == 'signal'):
       return -int(words[4])
   return default
 
 def FormatExitStatus(number):
   # Include the hex version because it makes the Windows error exit
   # statuses (STATUS_*) more recognisable.
   return '%i (0x%x)' % (number, number & 0xffffffff)
 
+def PrintStdStreams(stdout, stderr):
+  if stdout:

[Nick Bray, 2011/11/07 23:39:09]

The case in which stdout is printed has changed.  Are we printing too much?  In
what cases will stdout be printed?

[jvoung - send to chromium..., 2011/11/09 00:50:54]

Leaving this the same as before for now, as noted below.

+    Banner('Stdout for %s:' % os.path.basename(GlobalSettings['name']))
+    Print(stdout)
+  if stderr:

[Nick Bray, 2011/11/07 23:39:09]

is not None?
!= ''?
It's hard to tell what your intent is.  If you're legitimately trying to check
for both, I think it's a smell something else wrong. 

[jvoung - send to chromium..., 2011/11/09 00:50:54]

Hmm... I don't remember why I did that change anymore. I'll leave the condition
the same. They should both be not None, or both be None.

+    Banner('Stderr for %s:' % os.path.basename(GlobalSettings['name']))
+    Print(stderr)
+
 def CheckExitStatus(failed, req_status, using_nacl_signal_handler,
                     exit_status, stdout, stderr):
   expected_sigtype = 'normal'
   if req_status in status_map:
     expected_statuses = status_map[req_status][GlobalPlatform]
     if using_nacl_signal_handler:
       if req_status.startswith('trusted_'):
         expected_sigtype = 'trusted'
       elif req_status.startswith('untrusted_'):
         expected_sigtype = 'untrusted'
@@ skipping 38 matching lines @@
     expected_printed = (expected_printed_signum, expected_sigtype)
     actual_printed = GetNaClSignalInfoFromStderr(stderr)
     msg = ('\nERROR: Command printed the signal info %s to stderr '
            'but we expected %s' %
            (actual_printed, expected_printed))
     if actual_printed != expected_printed:
       Print(msg)
       failed = True
 
   if failed:
-    if stderr is not None:
-      Banner('Stdout')
-      Print(stdout)
-      Banner('Stderr')
-      Print(stderr)
+    PrintStdStreams(stdout, stderr)
   return not failed
 
 def CheckTimeBounds(total_time):
   if GlobalSettings['time_error']:
     if total_time > GlobalSettings['time_error']:
       Print('ERROR: should have taken less than %f secs' %
             (GlobalSettings['time_error']))
       return False
 
   if GlobalSettings['time_warning']:
@@ skipping 14 matching lines @@
       actual = getter()
       if GlobalSettings['filter_regex']:
         actual = test_lib.RegexpFilterLines(GlobalSettings['filter_regex'],
                                             GlobalSettings['filter_inverse'],
                                             GlobalSettings['filter_group_only'],
                                             actual)
       if DifferentFromGolden(actual, golden_data, stream):
         return False
   return True
 
-def ProcessLogOutput(stdout, stderr):
-  output_processor = GlobalSettings['process_output']
-  if output_processor:
+def ProcessLogOutputSingle(stdout, stderr):
+  output_processor = GlobalSettings['process_output_single']
+  if not output_processor:
+    return (True, stdout, stderr)
+  else:
     output_processor_cmd = DestringifyList(output_processor)
-    # Also, get the output from logout (to get NaClLog output in Windows).
+    # Also, get the output from log_file to get NaClLog output in Windows.
     log_output = open(GlobalSettings['log_file']).read()
     # Assume the log processor does not care about the order of the lines.
     all_output = log_output + stdout + stderr
-    if not test_lib.RunCmdWithInput(output_processor_cmd, all_output):
+    _, retcode, failed, new_stdout, new_stderr = \
+        test_lib.RunTestWithInputOutput(output_processor_cmd, all_output)
+    # Print the result, since we have done some processing and we need
+    # to have the processed data. However, if we intend to process it some
+    # more later via process_output_combined, do not duplicate the data here.
+    # Only print out the final result!
+    if not GlobalSettings['process_output_combined']:
+      PrintStdStreams(new_stdout, new_stderr)
+    if retcode != 0 or failed:
+      return (False, new_stdout, new_stderr)
+    else:
+      return (True, new_stdout, new_stderr)
+
+def ProcessLogOutputCombined(stdout, stderr):
+  output_processor = GlobalSettings['process_output_combined']
+  if not output_processor:
+    return True
+  else:
+    output_processor_cmd = DestringifyList(output_processor)
+    all_output = stdout + stderr
+    _, retcode, failed, new_stdout, new_stderr = \
+        test_lib.RunTestWithInputOutput(output_processor_cmd, all_output)
+    # Print the result, since we have done some processing.
+    PrintStdStreams(new_stdout, new_stderr)
+    if retcode != 0 or failed:
       return False
-  return True
+    else:
+      return True
 
-def main(argv):
-  global GlobalPlatform
-  global GlobalReportStream
-  command = ProcessOptions(argv)
-
-  if GlobalSettings['report']:
-    GlobalReportStream.append(open(GlobalSettings['report'], 'w'))
-
-  if not GlobalSettings['name']:
-    GlobalSettings['name'] = command[0]
-  GlobalSettings['name'] = os.path.basename(GlobalSettings['name'])
-
-  Print(RunMessage())
-
-  if GlobalSettings['osenv']:
-    Banner('setting environment')
-    env_vars = DestringifyList(GlobalSettings['osenv'])
-  else:
-    env_vars = []
-  for env_var in env_vars:
-    key, val = env_var.split('=', 1)
-    Print('[%s] = [%s]' % (key, val))
-    os.putenv(key, val)
-
-  stdin_data = ''
-  if GlobalSettings['stdin']:
-    stdin_data = open(GlobalSettings['stdin'])
-
-  if GlobalSettings['log_file']:
-    try:
-      os.unlink(GlobalSettings['log_file'])  # might not pre-exist
-    except OSError:
-      pass
-
-  run_under = GlobalSettings['run_under']
-  if run_under:
-    command = run_under.split(',') + command
-
-  Banner('running %s' % str(command))
-  # print the command in copy-and-pastable fashion
-  print " ".join(env_vars + command)
-
+def DoRun(command, stdin_data):
+  """
+  Run the command, given stdin_data. Returns a return code (0 is good)
+  and optionally a captured version of stdout, stderr from the run
+  (if the global setting capture_output is true).
+  """
+  # Initialize stdout, stderr to indicate we have not captured
+  # any of stdout or stderr.
+  stdout = ''
+  stderr = ''
   if not int(GlobalSettings['capture_output']):
     # We are only blurting out the stdout and stderr, not capturing it
     # for comparison, etc.
     assert (not GlobalSettings['stdout_golden']
             and not GlobalSettings['stderr_golden']
             and not GlobalSettings['log_golden']
             and not GlobalSettings['filter_regex']
             and not GlobalSettings['filter_inverse']
             and not GlobalSettings['filter_group_only']
-            and not GlobalSettings['process_output']
+            and not GlobalSettings['process_output_single']
+            and not GlobalSettings['process_output_combined']
             )
     # If python ever changes popen.stdout.read() to not risk deadlock,
     # we could stream and capture, and use RunTestWithInputOutput instead.
     (total_time, exit_status, failed) = test_lib.RunTestWithInput(command,
                                                                   stdin_data)
     PrintTotalTime(total_time)
     if not CheckExitStatus(failed,
                            GlobalSettings['exit_status'],
                            GlobalSettings['using_nacl_signal_handler'],
                            exit_status, None, None):
       Print(FailureMessage(total_time))
-      return -1
+      return (-1, stdout, stderr)
   else:
     (total_time, exit_status,
      failed, stdout, stderr) = test_lib.RunTestWithInputOutput(
          command, stdin_data)
     PrintTotalTime(total_time)
+    # CheckExitStatus may spew stdout/stderr when there is an error.
+    # Otherwise, we do not spew stdout/stderr in this case (capture_output).
     if not CheckExitStatus(failed,
                            GlobalSettings['exit_status'],
                            GlobalSettings['using_nacl_signal_handler'],
                            exit_status, stdout, stderr):
       Print(FailureMessage(total_time))
-      return -1
+      return (-1, stdout, stderr)
     if not CheckGoldenOutput(stdout, stderr):
       Print(FailureMessage(total_time))
-      return -1
-    if not ProcessLogOutput(stdout, stderr):
-      Print(FailureMessage(total_time))
-      return -1
+      return (-1, stdout, stderr)
+    success, stdout, stderr = ProcessLogOutputSingle(stdout, stderr)
+    if not success:
+      Print(FailureMessage(total_time) + ' ProcessLogOutputSingle failed!')
+      return (-1, stdout, stderr)
 
   if not CheckTimeBounds(total_time):
     Print(FailureMessage(total_time))
-    return -1
+    return (-1, stdout, stderr)
 
   Print(SuccessMessage(total_time))
+  return (0, stdout, stderr)
+
+
+def main(argv):

[Nick Bray, 2011/11/07 23:39:09]

Capitalize

[jvoung - send to chromium..., 2011/11/09 00:50:54]

capitalize Main? ok.

+  global GlobalPlatform

[Nick Bray, 2011/11/07 23:39:09]

Do not declare globals unless you assign directly to the global variable.

... particularly because it's called "Global" - no confusion, there.

[jvoung - send to chromium..., 2011/11/09 00:50:54]

Done.

+  global GlobalReportStream
+  command = ProcessOptions(argv)
+
+  if GlobalSettings['report']:
+    GlobalReportStream.append(open(GlobalSettings['report'], 'w'))
+
+  if not GlobalSettings['name']:
+    GlobalSettings['name'] = command[0]
+  GlobalSettings['name'] = os.path.basename(GlobalSettings['name'])
+
+  Print(RunMessage())
+
+  if GlobalSettings['osenv']:
+    Banner('setting environment')
+    env_vars = DestringifyList(GlobalSettings['osenv'])
+  else:
+    env_vars = []
+  for env_var in env_vars:
+    key, val = env_var.split('=', 1)
+    Print('[%s] = [%s]' % (key, val))
+    os.putenv(key, val)

[Nick Bray, 2011/11/07 23:39:09]

putenv considered harmful.  Assign to os.environ?

[jvoung - send to chromium..., 2011/11/09 00:50:54]

Don't know the specifics (does it sometimes not work?)... but okay.

+
+  stdin_data = ''
+  if GlobalSettings['stdin']:
+    stdin_data = open(GlobalSettings['stdin'])
+
+  run_under = GlobalSettings['run_under']
+  if run_under:
+    command = run_under.split(',') + command
+
+  Banner('running %s' % str(command))
+  # print the command in copy-and-pastable fashion
+  print " ".join(env_vars + command)
+
+  # Concatenate output when running multiple times (e.g., for timing).
+  combined_stdout = ''
+  combined_stderr = ''
+  cur_runs = 0
+  num_runs = int(GlobalSettings['num_runs'])
+  while cur_runs < num_runs:
+    cur_runs += 1
+    # Clear out previous log_file.
+    if GlobalSettings['log_file']:
+      try:
+        os.unlink(GlobalSettings['log_file'])  # might not pre-exist
+      except OSError:
+        pass
+    ret_code, stdout, stderr = DoRun(command, stdin_data)
+    if ret_code != 0:
+      return ret_code
+    combined_stdout += stdout
+    combined_stderr += stderr
+  # Process the log output after all the runs.
+  success = ProcessLogOutputCombined(combined_stdout, combined_stderr)
+  if not success:
+    # Bogus time, since only ProcessLogOutputCombined failed.
+    Print(FailureMessage(0.0) + ' ProcessLogOutputCombined failed!')
+    return -1
   return 0
 
-
 if __name__ == '__main__':
   retval = main(sys.argv[1:])
   # Add some whitepsace to make the logs easier to read.
   sys.stdout.write('\n\n')
   sys.exit(retval)
-