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

.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:

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)
 
 

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)'

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 \