bpo-30283: Backport regrtest features from master to 2.7 (#1516) · python/cpython@453a685
@@ -27,7 +27,7 @@
2727-w/--verbose2 -- re-run failed tests in verbose mode
2828-W/--verbose3 -- re-run failed tests in verbose mode immediately
2929-q/--quiet -- no output unless one or more tests fail
30--S/--slow -- print the slowest 10 tests
30+-S/--slowest -- print the slowest 10 tests
3131 --header -- print header with interpreter info
32323333Selecting tests
6262-P/--pgo -- enable Profile Guided Optimization training
6363--testdir -- execute test files in the specified directory
6464 (instead of the Python stdlib test suite)
65+--list-tests -- only write the name of tests that will be run,
66+ don't execute them
656766686769Additional Option Details:
158160"""
159161160162import StringIO
163+import datetime
161164import getopt
162165import json
163166import os
226229INTERRUPTED = -4
227230CHILD_ERROR = -5 # error in a child process
228231232+# Minimum duration of a test to display its duration or to mention that
233+# the test is running in background
234+PROGRESS_MIN_TIME = 30.0 # seconds
235+236+# Display the running tests if nothing happened last N seconds
237+PROGRESS_UPDATE = 30.0 # seconds
238+229239from test import test_support
230240231241RESOURCE_NAMES = ('audio', 'curses', 'largefile', 'network', 'bsddb',
@@ -241,6 +251,32 @@ def usage(code, msg=''):
241251sys.exit(code)
242252243253254+def format_duration(seconds):
255+if seconds < 1.0:
256+return '%.0f ms' % (seconds * 1e3)
257+if seconds < 60.0:
258+return '%.0f sec' % seconds
259+260+minutes, seconds = divmod(seconds, 60.0)
261+return '%.0f min %.0f sec' % (minutes, seconds)
262+263+264+_FORMAT_TEST_RESULT = {
265+PASSED: '%s passed',
266+FAILED: '%s failed',
267+ENV_CHANGED: '%s failed (env changed)',
268+SKIPPED: '%s skipped',
269+RESOURCE_DENIED: '%s skipped (resource denied)',
270+INTERRUPTED: '%s interrupted',
271+CHILD_ERROR: '%s crashed',
272+}
273+274+275+def format_test_result(test_name, result):
276+fmt = _FORMAT_TEST_RESULT.get(result, "%s")
277+return fmt % test_name
278+279+244280def main(tests=None, testdir=None, verbose=0, quiet=False,
245281exclude=False, single=False, randomize=False, fromfile=None,
246282findleaks=False, use_resources=None, trace=False, coverdir='coverage',
@@ -269,16 +305,18 @@ def main(tests=None, testdir=None, verbose=0, quiet=False,
269305 directly to set the values that would normally be set by flags
270306 on the command line.
271307 """
308+regrtest_start_time = time.time()
272309273310test_support.record_original_stdout(sys.stdout)
274311try:
275312opts, args = getopt.getopt(sys.argv[1:], 'hvqxsSrf:lu:t:TD:NLR:FwWM:j:PGm:',
276313 ['help', 'verbose', 'verbose2', 'verbose3', 'quiet',
277-'exclude', 'single', 'slow', 'randomize', 'fromfile=', 'findleaks',
314+'exclude', 'single', 'slow', 'slowest', 'randomize', 'fromfile=',
315+'findleaks',
278316'use=', 'threshold=', 'trace', 'coverdir=', 'nocoverdir',
279317'runleaks', 'huntrleaks=', 'memlimit=', 'randseed=',
280318'multiprocess=', 'slaveargs=', 'forever', 'header', 'pgo',
281-'failfast', 'match=', 'testdir='])
319+'failfast', 'match=', 'testdir=', 'list-tests'])
282320except getopt.error, msg:
283321usage(2, msg)
284322@@ -288,6 +326,7 @@ def main(tests=None, testdir=None, verbose=0, quiet=False,
288326if use_resources is None:
289327use_resources = []
290328slaveargs = None
329+list_tests = False
291330for o, a in opts:
292331if o in ('-h', '--help'):
293332usage(0)
@@ -306,7 +345,7 @@ def main(tests=None, testdir=None, verbose=0, quiet=False,
306345exclude = True
307346elif o in ('-s', '--single'):
308347single = True
309-elif o in ('-S', '--slow'):
348+elif o in ('-S', '--slow', '--slowest'):
310349print_slow = True
311350elif o in ('-r', '--randomize'):
312351randomize = True
@@ -373,8 +412,10 @@ def main(tests=None, testdir=None, verbose=0, quiet=False,
373412slaveargs = a
374413elif o in ('-P', '--pgo'):
375414pgo = True
376-elif o in ('--testdir'):
415+elif o == '--testdir':
377416testdir = a
417+elif o == '--list-tests':
418+list_tests = True
378419else:
379420print >>sys.stderr, ("No handler for option {}. Please "
380421"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,
482523random.seed(random_seed)
483524print "Using random seed", random_seed
484525random.shuffle(selected)
526+527+if list_tests:
528+for name in selected:
529+print(name)
530+sys.exit(0)
531+485532if trace:
486533import trace
487534tracer = trace.Trace(ignoredirs=[sys.prefix, sys.exec_prefix],
@@ -525,13 +572,27 @@ def test_forever(tests=list(selected)):
525572test_count = '/{}'.format(len(selected))
526573test_count_width = len(test_count) - 1
527574575+def display_progress(test_index, test):
576+# "[ 51/405/1] test_tcl"
577+fmt = "[{1:{0}}{2}/{3}] {4}" if bad else "[{1:{0}}{2}] {4}"
578+line = fmt.format(test_count_width, test_index, test_count,
579+len(bad), test)
580+581+# add the timestamp prefix: "0:01:05 "
582+test_time = time.time() - regrtest_start_time
583+test_time = datetime.timedelta(seconds=int(test_time))
584+line = "%s %s" % (test_time, line)
585+586+print(line)
587+sys.stdout.flush()
588+528589if use_mp:
529590try:
530591from threading import Thread
531592except ImportError:
532593print "Multiprocess option requires thread support"
533594sys.exit(2)
534-from Queue import Queue
595+from Queue import Queue, Empty
535596from subprocess import Popen, PIPE
536597debug_output_pat = re.compile(r"\[\d+ refs\]$")
537598output = Queue()
@@ -551,63 +612,106 @@ def tests_and_args():
551612# required to spawn a new process with PGO flag on/off
552613if pgo:
553614base_cmd = base_cmd + ['--pgo']
554-def work():
555-# A worker thread.
556-try:
557-while True:
558-try:
559-test, args_tuple = next(pending)
560-except StopIteration:
561-output.put((None, None, None, None))
562-return
563-# -E is needed by some tests, e.g. test_import
564-args = base_cmd + ['--slaveargs', json.dumps(args_tuple)]
565-if testdir:
566-args.extend(('--testdir', testdir))
615+616+class MultiprocessThread(Thread):
617+current_test = None
618+start_time = None
619+620+def runtest(self):
621+try:
622+test, args_tuple = next(pending)
623+except StopIteration:
624+output.put((None, None, None, None))
625+return True
626+627+# -E is needed by some tests, e.g. test_import
628+args = base_cmd + ['--slaveargs', json.dumps(args_tuple)]
629+if testdir:
630+args.extend(('--testdir', testdir))
631+try:
632+self.start_time = time.time()
633+self.current_test = test
567634popen = Popen(args,
568635stdout=PIPE, stderr=PIPE,
569636universal_newlines=True,
570637close_fds=(os.name != 'nt'))
571638stdout, stderr = popen.communicate()
572639retcode = popen.wait()
640+finally:
641+self.current_test = None
573642574- # Strip last refcount output line if it exists, since it
575- # comes from the shutdown of the interpreter in the subcommand.
576- stderr = debug_output_pat.sub("", stderr)
643+# Strip last refcount output line if it exists, since it
644+# comes from the shutdown of the interpreter in the subcommand.
645+stderr = debug_output_pat.sub("", stderr)
577646578- if retcode == 0:
579- stdout, _, result = stdout.strip().rpartition("\n")
580- if not result:
581- output.put((None, None, None, None))
582- return
647+if retcode == 0:
648+stdout, _, result = stdout.strip().rpartition("\n")
649+if not result:
650+output.put((None, None, None, None))
651+return True
583652584- result = json.loads(result)
585- else:
586- result = (CHILD_ERROR, "Exit code %s" % retcode)
653+result = json.loads(result)
654+else:
655+result = (CHILD_ERROR, "Exit code %s" % retcode)
587656588-output.put((test, stdout.rstrip(), stderr.rstrip(), result))
589-except BaseException:
590-output.put((None, None, None, None))
591-raise
657+output.put((test, stdout.rstrip(), stderr.rstrip(), result))
658+return False
592659593-workers = [Thread(target=work) for i in range(use_mp)]
660+def run(self):
661+try:
662+stop = False
663+while not stop:
664+stop = self.runtest()
665+except BaseException:
666+output.put((None, None, None, None))
667+raise
668+669+workers = [MultiprocessThread() for i in range(use_mp)]
670+print("Run tests in parallel using %s child processes"
671+% len(workers))
594672for worker in workers:
595673worker.start()
596674675+def get_running(workers):
676+running = []
677+for worker in workers:
678+current_test = worker.current_test
679+if not current_test:
680+continue
681+dt = time.time() - worker.start_time
682+if dt >= PROGRESS_MIN_TIME:
683+running.append('%s (%.0f sec)' % (current_test, dt))
684+return running
685+597686finished = 0
598687test_index = 1
688+get_timeout = max(PROGRESS_UPDATE, PROGRESS_MIN_TIME)
599689try:
600690while finished < use_mp:
601-test, stdout, stderr, result = output.get()
691+try:
692+item = output.get(timeout=get_timeout)
693+except Empty:
694+running = get_running(workers)
695+if running and not pgo:
696+print('running: %s' % ', '.join(running))
697+continue
698+699+test, stdout, stderr, result = item
602700if test is None:
603701finished += 1
604702continue
605703accumulate_result(test, result)
606704if not quiet:
607-fmt = "[{1:{0}}{2}/{3}] {4}" if bad else "[{1:{0}}{2}] {4}"
608-print(fmt.format(
609-test_count_width, test_index, test_count,
610-len(bad), test))
705+ok, test_time = result
706+text = format_test_result(test, ok)
707+if (ok not in (CHILD_ERROR, INTERRUPTED)
708+and test_time >= PROGRESS_MIN_TIME
709+and not pgo):
710+text += ' (%.0f sec)' % test_time
711+running = get_running(workers)
712+if running and not pgo:
713+text += ' -- running: %s' % ', '.join(running)
714+display_progress(test_index, text)
611715612716if stdout:
613717print stdout
@@ -627,18 +731,22 @@ def work():
627731for worker in workers:
628732worker.join()
629733else:
734+print("Run tests sequentially")
735+736+previous_test = None
630737for test_index, test in enumerate(tests, 1):
631738if not quiet:
632-fmt = "[{1:{0}}{2}/{3}] {4}" if bad else "[{1:{0}}{2}] {4}"
633-print(fmt.format(
634-test_count_width, test_index, test_count, len(bad), test))
635-sys.stdout.flush()
739+text = test
740+if previous_test:
741+text = '%s -- %s' % (text, previous_test)
742+display_progress(test_index, text)
636743if trace:
637744# If we're tracing code coverage, then we don't exit with status
638745# if on a false return value from main.
639746tracer.runctx('runtest(test, verbose, quiet, testdir=testdir)',
640747globals=globals(), locals=vars())
641748else:
749+start_time = time.time()
642750try:
643751result = runtest(test, verbose, quiet, huntrleaks, None, pgo,
644752failfast=failfast,
@@ -655,6 +763,16 @@ def work():
655763break
656764except:
657765raise
766+767+previous_test = format_test_result(test, result[0])
768+test_time = time.time() - start_time
769+if test_time >= PROGRESS_MIN_TIME:
770+previous_test = "%s in %s" % (previous_test,
771+format_duration(test_time))
772+elif result[0] == PASSED:
773+# be quiet: say nothing if the test passed shortly
774+previous_test = None
775+658776if findleaks:
659777gc.collect()
660778if gc.garbage:
@@ -683,8 +801,8 @@ def work():
683801if print_slow:
684802test_times.sort(reverse=True)
685803print "10 slowest tests:"
686-for time, test in test_times[:10]:
687-print "%s: %.1fs" % (test, time)
804+for test_time, test in test_times[:10]:
805+print("- %s: %.1fs" % (test, test_time))
688806if bad and not pgo:
689807print count(len(bad), "test"), "failed:"
690808printlist(bad)
@@ -745,6 +863,18 @@ def work():
745863if runleaks:
746864os.system("leaks %d" % os.getpid())
747865866+print
867+duration = time.time() - regrtest_start_time
868+print("Total duration: %s" % format_duration(duration))
869+870+if bad:
871+result = "FAILURE"
872+elif interrupted:
873+result = "INTERRUPTED"
874+else:
875+result = "SUCCESS"
876+print("Tests result: %s" % result)
877+748878sys.exit(len(bad) > 0 or interrupted)
749879750880