From: Victor Stinner Date: Tue, 9 May 2017 15:06:34 +0000 (+0200) Subject: bpo-30283: Backport regrtest features from master to 2.7 (#1516) X-Git-Tag: v2.7.14rc1~162 X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=453a6857023a0a2c714772cda8717ecf03de64f5;p=python bpo-30283: Backport regrtest features from master to 2.7 (#1516) * regrtest: add --slowest alias to --slow * make buildbottest: add --slowest option * regrtest: add "- " prefix to --slowest output * regrtest: Fix an outdated comment * regrtest: replace PermissionError Replace PermissionError with OSError and check on exc.errno. PermissionError was added to Python 3.3. * regrtest: add -3 -tt options to run Python scripts * regrtest: backport --list-tests option * regrtest: backport "Tests result: xxx" summary * regrtest: backport total duration * regrtest: add timestamp to the progress * regrtest: describe previous test state * Add the state of the test: passed, failed, etc. * If a test took longer than 30 seconds, log its execution time * regrtest: -jN logs running workers * regrtest: mention if tests are run in parallel * regrtest: parallel mode is more verbose during wait Display running tests every 30 seconds if no test completed in the meanwhile. * test_regrtest: fix typo in SubprocessRun --- diff --git a/.github/appveyor.yml b/.github/appveyor.yml index f42cdc9273..56ef344458 100644 --- a/.github/appveyor.yml +++ b/.github/appveyor.yml @@ -3,7 +3,7 @@ clone_depth: 5 build_script: - cmd: PCbuild\build.bat -e test_script: -- cmd: PCbuild\rt.bat -q -uall -rwW --slow -j2 +- cmd: PCbuild\rt.bat -q -uall -rwW --slowest -j2 # Only trigger AppVeyor if actual code or its configuration changes only_commits: diff --git a/Lib/test/regrtest.py b/Lib/test/regrtest.py index 9bcf14f1b2..37781fcc01 100755 --- a/Lib/test/regrtest.py +++ b/Lib/test/regrtest.py @@ -27,7 +27,7 @@ Verbosity -w/--verbose2 -- re-run failed tests in verbose mode -W/--verbose3 -- re-run failed tests in verbose mode immediately -q/--quiet -- no output unless one or more tests fail --S/--slow -- print the slowest 10 tests +-S/--slowest -- print the slowest 10 tests --header -- print header with interpreter info Selecting tests @@ -62,6 +62,8 @@ Special runs -P/--pgo -- enable Profile Guided Optimization training --testdir -- execute test files in the specified directory (instead of the Python stdlib test suite) +--list-tests -- only write the name of tests that will be run, + don't execute them Additional Option Details: @@ -158,6 +160,7 @@ option '-uall,-bsddb'. """ import StringIO +import datetime import getopt import json import os @@ -226,6 +229,13 @@ RESOURCE_DENIED = -3 INTERRUPTED = -4 CHILD_ERROR = -5 # error in a child process +# Minimum duration of a test to display its duration or to mention that +# the test is running in background +PROGRESS_MIN_TIME = 30.0 # seconds + +# Display the running tests if nothing happened last N seconds +PROGRESS_UPDATE = 30.0 # seconds + from test import test_support RESOURCE_NAMES = ('audio', 'curses', 'largefile', 'network', 'bsddb', @@ -241,6 +251,32 @@ def usage(code, msg=''): sys.exit(code) +def format_duration(seconds): + if seconds < 1.0: + return '%.0f ms' % (seconds * 1e3) + if seconds < 60.0: + return '%.0f sec' % seconds + + minutes, seconds = divmod(seconds, 60.0) + return '%.0f min %.0f sec' % (minutes, seconds) + + +_FORMAT_TEST_RESULT = { + PASSED: '%s passed', + FAILED: '%s failed', + ENV_CHANGED: '%s failed (env changed)', + SKIPPED: '%s skipped', + RESOURCE_DENIED: '%s skipped (resource denied)', + INTERRUPTED: '%s interrupted', + CHILD_ERROR: '%s crashed', +} + + +def format_test_result(test_name, result): + fmt = _FORMAT_TEST_RESULT.get(result, "%s") + return fmt % test_name + + def main(tests=None, testdir=None, verbose=0, quiet=False, exclude=False, single=False, randomize=False, fromfile=None, findleaks=False, use_resources=None, trace=False, coverdir='coverage', @@ -269,16 +305,18 @@ def main(tests=None, testdir=None, verbose=0, quiet=False, directly to set the values that would normally be set by flags on the command line. """ + regrtest_start_time = time.time() test_support.record_original_stdout(sys.stdout) try: opts, args = getopt.getopt(sys.argv[1:], 'hvqxsSrf:lu:t:TD:NLR:FwWM:j:PGm:', ['help', 'verbose', 'verbose2', 'verbose3', 'quiet', - 'exclude', 'single', 'slow', 'randomize', 'fromfile=', 'findleaks', + 'exclude', 'single', 'slow', 'slowest', 'randomize', 'fromfile=', + 'findleaks', 'use=', 'threshold=', 'trace', 'coverdir=', 'nocoverdir', 'runleaks', 'huntrleaks=', 'memlimit=', 'randseed=', 'multiprocess=', 'slaveargs=', 'forever', 'header', 'pgo', - 'failfast', 'match=', 'testdir=']) + 'failfast', 'match=', 'testdir=', 'list-tests']) except getopt.error, msg: usage(2, msg) @@ -288,6 +326,7 @@ def main(tests=None, testdir=None, verbose=0, quiet=False, if use_resources is None: use_resources = [] slaveargs = None + list_tests = False for o, a in opts: if o in ('-h', '--help'): usage(0) @@ -306,7 +345,7 @@ def main(tests=None, testdir=None, verbose=0, quiet=False, exclude = True elif o in ('-s', '--single'): single = True - elif o in ('-S', '--slow'): + elif o in ('-S', '--slow', '--slowest'): print_slow = True elif o in ('-r', '--randomize'): randomize = True @@ -373,8 +412,10 @@ def main(tests=None, testdir=None, verbose=0, quiet=False, slaveargs = a elif o in ('-P', '--pgo'): pgo = True - elif o in ('--testdir'): + elif o == '--testdir': testdir = a + elif o == '--list-tests': + list_tests = True else: print >>sys.stderr, ("No handler for option {}. Please " "report this as a bug at http://bugs.python.org.").format(o) @@ -482,6 +523,12 @@ def main(tests=None, testdir=None, verbose=0, quiet=False, random.seed(random_seed) print "Using random seed", random_seed random.shuffle(selected) + + if list_tests: + for name in selected: + print(name) + sys.exit(0) + if trace: import trace tracer = trace.Trace(ignoredirs=[sys.prefix, sys.exec_prefix], @@ -525,13 +572,27 @@ def main(tests=None, testdir=None, verbose=0, quiet=False, test_count = '/{}'.format(len(selected)) test_count_width = len(test_count) - 1 + def display_progress(test_index, test): + # "[ 51/405/1] test_tcl" + fmt = "[{1:{0}}{2}/{3}] {4}" if bad else "[{1:{0}}{2}] {4}" + line = fmt.format(test_count_width, test_index, test_count, + len(bad), test) + + # add the timestamp prefix: "0:01:05 " + test_time = time.time() - regrtest_start_time + test_time = datetime.timedelta(seconds=int(test_time)) + line = "%s %s" % (test_time, line) + + print(line) + sys.stdout.flush() + if use_mp: try: from threading import Thread except ImportError: print "Multiprocess option requires thread support" sys.exit(2) - from Queue import Queue + from Queue import Queue, Empty from subprocess import Popen, PIPE debug_output_pat = re.compile(r"\[\d+ refs\]$") output = Queue() @@ -551,63 +612,106 @@ def main(tests=None, testdir=None, verbose=0, quiet=False, # required to spawn a new process with PGO flag on/off if pgo: base_cmd = base_cmd + ['--pgo'] - def work(): - # A worker thread. - try: - while True: - try: - test, args_tuple = next(pending) - except StopIteration: - output.put((None, None, None, None)) - return - # -E is needed by some tests, e.g. test_import - args = base_cmd + ['--slaveargs', json.dumps(args_tuple)] - if testdir: - args.extend(('--testdir', testdir)) + + class MultiprocessThread(Thread): + current_test = None + start_time = None + + def runtest(self): + try: + test, args_tuple = next(pending) + except StopIteration: + output.put((None, None, None, None)) + return True + + # -E is needed by some tests, e.g. test_import + args = base_cmd + ['--slaveargs', json.dumps(args_tuple)] + if testdir: + args.extend(('--testdir', testdir)) + try: + self.start_time = time.time() + self.current_test = test popen = Popen(args, stdout=PIPE, stderr=PIPE, universal_newlines=True, close_fds=(os.name != 'nt')) stdout, stderr = popen.communicate() retcode = popen.wait() + finally: + self.current_test = None - # Strip last refcount output line if it exists, since it - # comes from the shutdown of the interpreter in the subcommand. - stderr = debug_output_pat.sub("", stderr) + # Strip last refcount output line if it exists, since it + # comes from the shutdown of the interpreter in the subcommand. + stderr = debug_output_pat.sub("", stderr) - if retcode == 0: - stdout, _, result = stdout.strip().rpartition("\n") - if not result: - output.put((None, None, None, None)) - return + if retcode == 0: + stdout, _, result = stdout.strip().rpartition("\n") + if not result: + output.put((None, None, None, None)) + return True - result = json.loads(result) - else: - result = (CHILD_ERROR, "Exit code %s" % retcode) + result = json.loads(result) + else: + result = (CHILD_ERROR, "Exit code %s" % retcode) - output.put((test, stdout.rstrip(), stderr.rstrip(), result)) - except BaseException: - output.put((None, None, None, None)) - raise + output.put((test, stdout.rstrip(), stderr.rstrip(), result)) + return False - workers = [Thread(target=work) for i in range(use_mp)] + def run(self): + try: + stop = False + while not stop: + stop = self.runtest() + except BaseException: + output.put((None, None, None, None)) + raise + + workers = [MultiprocessThread() for i in range(use_mp)] + print("Run tests in parallel using %s child processes" + % len(workers)) for worker in workers: worker.start() + def get_running(workers): + running = [] + for worker in workers: + current_test = worker.current_test + if not current_test: + continue + dt = time.time() - worker.start_time + if dt >= PROGRESS_MIN_TIME: + running.append('%s (%.0f sec)' % (current_test, dt)) + return running + finished = 0 test_index = 1 + get_timeout = max(PROGRESS_UPDATE, PROGRESS_MIN_TIME) try: while finished < use_mp: - test, stdout, stderr, result = output.get() + try: + item = output.get(timeout=get_timeout) + except Empty: + running = get_running(workers) + if running and not pgo: + print('running: %s' % ', '.join(running)) + continue + + test, stdout, stderr, result = item if test is None: finished += 1 continue accumulate_result(test, result) if not quiet: - fmt = "[{1:{0}}{2}/{3}] {4}" if bad else "[{1:{0}}{2}] {4}" - print(fmt.format( - test_count_width, test_index, test_count, - len(bad), test)) + ok, test_time = result + text = format_test_result(test, ok) + if (ok not in (CHILD_ERROR, INTERRUPTED) + and test_time >= PROGRESS_MIN_TIME + and not pgo): + text += ' (%.0f sec)' % test_time + running = get_running(workers) + if running and not pgo: + text += ' -- running: %s' % ', '.join(running) + display_progress(test_index, text) if stdout: print stdout @@ -627,18 +731,22 @@ def main(tests=None, testdir=None, verbose=0, quiet=False, for worker in workers: worker.join() else: + print("Run tests sequentially") + + previous_test = None for test_index, test in enumerate(tests, 1): if not quiet: - fmt = "[{1:{0}}{2}/{3}] {4}" if bad else "[{1:{0}}{2}] {4}" - print(fmt.format( - test_count_width, test_index, test_count, len(bad), test)) - sys.stdout.flush() + text = test + if previous_test: + text = '%s -- %s' % (text, previous_test) + display_progress(test_index, text) if trace: # If we're tracing code coverage, then we don't exit with status # if on a false return value from main. tracer.runctx('runtest(test, verbose, quiet, testdir=testdir)', globals=globals(), locals=vars()) else: + start_time = time.time() try: result = runtest(test, verbose, quiet, huntrleaks, None, pgo, failfast=failfast, @@ -655,6 +763,16 @@ def main(tests=None, testdir=None, verbose=0, quiet=False, break except: raise + + previous_test = format_test_result(test, result[0]) + test_time = time.time() - start_time + if test_time >= PROGRESS_MIN_TIME: + previous_test = "%s in %s" % (previous_test, + format_duration(test_time)) + elif result[0] == PASSED: + # be quiet: say nothing if the test passed shortly + previous_test = None + if findleaks: gc.collect() if gc.garbage: @@ -683,8 +801,8 @@ def main(tests=None, testdir=None, verbose=0, quiet=False, if print_slow: test_times.sort(reverse=True) print "10 slowest tests:" - for time, test in test_times[:10]: - print "%s: %.1fs" % (test, time) + for test_time, test in test_times[:10]: + print("- %s: %.1fs" % (test, test_time)) if bad and not pgo: print count(len(bad), "test"), "failed:" printlist(bad) @@ -745,6 +863,18 @@ def main(tests=None, testdir=None, verbose=0, quiet=False, if runleaks: os.system("leaks %d" % os.getpid()) + print + duration = time.time() - regrtest_start_time + print("Total duration: %s" % format_duration(duration)) + + if bad: + result = "FAILURE" + elif interrupted: + result = "INTERRUPTED" + else: + result = "SUCCESS" + print("Tests result: %s" % result) + sys.exit(len(bad) > 0 or interrupted) diff --git a/Lib/test/test_regrtest.py b/Lib/test/test_regrtest.py index 9f68d6b63e..211d1b53b5 100644 --- a/Lib/test/test_regrtest.py +++ b/Lib/test/test_regrtest.py @@ -6,6 +6,7 @@ Note: test_regrtest cannot be run twice in parallel. from __future__ import print_function import collections +import errno import os.path import platform import re @@ -33,7 +34,8 @@ TEST_INTERRUPTED = textwrap.dedent(""" """) -SubprocssRun = collections.namedtuple('SubprocssRun', 'returncode stdout, stderr') +SubprocessRun = collections.namedtuple('SubprocessRun', + 'returncode stdout stderr') class BaseTestCase(unittest.TestCase): @@ -58,13 +60,15 @@ class BaseTestCase(unittest.TestCase): path = os.path.join(self.tmptestdir, name + '.py') self.addCleanup(support.unlink, path) - # Use 'x' mode to ensure that we do not override existing tests + # Use O_EXCL to ensure that we do not override existing tests try: fd = os.open(path, os.O_WRONLY | os.O_CREAT | os.O_EXCL) - except PermissionError as exc: - if not sysconfig.is_python_build(): + except OSError as exc: + if (exc.errno in (errno.EACCES, errno.EPERM) + and not sysconfig.is_python_build()): self.skipTest("cannot write %s: %s" % (path, exc)) - raise + else: + raise else: with os.fdopen(fd, 'w') as fp: fp.write(code) @@ -81,7 +85,7 @@ class BaseTestCase(unittest.TestCase): self.assertRegexpMatches(output, regex) def parse_executed_tests(self, output): - regex = (r'^\[ *[0-9]+(?:/ *[0-9]+)*\] (%s)' + regex = (r'^[0-9]+:[0-9]+:[0-9]+ \[ *[0-9]+(?:/ *[0-9]+)*\] (%s)' % self.TESTNAME_REGEX) parser = re.finditer(regex, output, re.MULTILINE) return list(match.group(1) for match in parser) @@ -139,6 +143,14 @@ class BaseTestCase(unittest.TestCase): if interrupted: self.check_line(output, 'Test suite interrupted by signal SIGINT.') + if nfailed: + result = 'FAILURE' + elif interrupted: + result = 'INTERRUPTED' + else: + result = 'SUCCESS' + self.check_line(output, 'Tests result: %s' % result) + def parse_random_seed(self, output): match = self.regex_search(r'Using random seed ([0-9]+)', output) randseed = int(match.group(1)) @@ -171,7 +183,7 @@ class BaseTestCase(unittest.TestCase): "---\n" % stderr) self.fail(msg) - return SubprocssRun(proc.returncode, stdout, stderr) + return SubprocessRun(proc.returncode, stdout, stderr) def run_python(self, args, **kw): args = [sys.executable] + list(args) @@ -193,7 +205,7 @@ class ProgramsTestCase(BaseTestCase): # Create NTEST tests doing nothing self.tests = [self.create_test() for index in range(self.NTEST)] - self.python_args = ['-Wd', '-E', '-bb'] + self.python_args = ['-Wd', '-3', '-E', '-bb', '-tt'] self.regrtest_args = ['-uall', '-rwW', '--testdir=%s' % self.tmptestdir] @@ -370,13 +382,13 @@ class ArgsTestCase(BaseTestCase): self.check_executed_tests(output, test, omitted=test, interrupted=True) - def test_slow(self): + def test_slowest(self): # test --slow tests = [self.create_test() for index in range(3)] - output = self.run_tests("--slow", *tests) + output = self.run_tests("--slowest", *tests) self.check_executed_tests(output, tests) regex = ('10 slowest tests:\n' - '(?:%s: .*\n){%s}' + '(?:- %s: .*\n){%s}' % (self.TESTNAME_REGEX, len(tests))) self.check_line(output, regex) @@ -405,6 +417,13 @@ class ArgsTestCase(BaseTestCase): output = self.run_tests('--forever', test, exitcode=1) self.check_executed_tests(output, [test]*3, failed=test) + def test_list_tests(self): + # test --list-tests + tests = [self.create_test() for i in range(5)] + output = self.run_tests('--list-tests', *tests) + self.assertEqual(output.rstrip().splitlines(), + tests) + def test_crashed(self): # Any code which causes a crash code = 'import ctypes; ctypes.string_at(0)' diff --git a/Makefile.pre.in b/Makefile.pre.in index 32d8613b89..d12974cd9b 100644 --- a/Makefile.pre.in +++ b/Makefile.pre.in @@ -875,7 +875,7 @@ buildbottest: build_all platform -@if which pybuildbot.identify >/dev/null 2>&1; then \ pybuildbot.identify "CC='$(CC)'" "CXX='$(CXX)'"; \ fi - $(TESTPYTHON) -R $(TESTPROG) -uall -rwW $(TESTOPTS) + $(TESTPYTHON) -R $(TESTPROG) -uall --slowest -rwW $(TESTOPTS) QUICKTESTOPTS= $(TESTOPTS) -x test_subprocess test_io test_lib2to3 \ test_multibytecodec test_urllib2_localnet test_itertools \