Skip to content

Commit 453a685

Browse files
vstinnervstinner
authored
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
1 parent d2aff60 commit 453a685

File tree

4 files changed

+208
-59
lines changed

4 files changed

+208
-59
lines changed

‎.github/appveyor.yml‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,7 @@ clone_depth: 5
33
build_script:
44
- cmd: PCbuild\build.bat -e
55
test_script:
6-
- cmd: PCbuild\rt.bat -q -uall -rwW --slow -j2
6+
- cmd: PCbuild\rt.bat -q -uall -rwW --slowest -j2
77

88
# Only trigger AppVeyor if actual code or its configuration changes
99
only_commits:

‎Lib/test/regrtest.py‎

Lines changed: 176 additions & 46 deletions
Original file line numberDiff line numberDiff line change
@@ -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
3232
3333
Selecting tests
@@ -62,6 +62,8 @@
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
6567
6668
6769
Additional Option Details:
@@ -158,6 +160,7 @@
158160
"""
159161

160162
import StringIO
163+
import datetime
161164
import getopt
162165
import json
163166
import os
@@ -226,6 +229,13 @@
226229
INTERRUPTED = -4
227230
CHILD_ERROR = -5 # error in a child process
228231

232+
# 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+
229239
from test import test_support
230240

231241
RESOURCE_NAMES = ('audio', 'curses', 'largefile', 'network', 'bsddb',
@@ -241,6 +251,32 @@ def usage(code, msg=''):
241251
sys.exit(code)
242252

243253

254+
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+
244280
def main(tests=None, testdir=None, verbose=0, quiet=False,
245281
exclude=False, single=False, randomize=False, fromfile=None,
246282
findleaks=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()
272309

273310
test_support.record_original_stdout(sys.stdout)
274311
try:
275312
opts, 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'])
282320
except getopt.error, msg:
283321
usage(2, msg)
284322

@@ -288,6 +326,7 @@ def main(tests=None, testdir=None, verbose=0, quiet=False,
288326
if use_resources is None:
289327
use_resources = []
290328
slaveargs = None
329+
list_tests = False
291330
for o, a in opts:
292331
if o in ('-h', '--help'):
293332
usage(0)
@@ -306,7 +345,7 @@ def main(tests=None, testdir=None, verbose=0, quiet=False,
306345
exclude = True
307346
elif o in ('-s', '--single'):
308347
single = True
309-
elif o in ('-S', '--slow'):
348+
elif o in ('-S', '--slow', '--slowest'):
310349
print_slow = True
311350
elif o in ('-r', '--randomize'):
312351
randomize = True
@@ -373,8 +412,10 @@ def main(tests=None, testdir=None, verbose=0, quiet=False,
373412
slaveargs = a
374413
elif o in ('-P', '--pgo'):
375414
pgo = True
376-
elif o in ('--testdir'):
415+
elif o == '--testdir':
377416
testdir = a
417+
elif o == '--list-tests':
418+
list_tests = True
378419
else:
379420
print >>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,
482523
random.seed(random_seed)
483524
print "Using random seed", random_seed
484525
random.shuffle(selected)
526+
527+
if list_tests:
528+
for name in selected:
529+
print(name)
530+
sys.exit(0)
531+
485532
if trace:
486533
import trace
487534
tracer = trace.Trace(ignoredirs=[sys.prefix, sys.exec_prefix],
@@ -525,13 +572,27 @@ def test_forever(tests=list(selected)):
525572
test_count = '/{}'.format(len(selected))
526573
test_count_width = len(test_count) - 1
527574

575+
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+
528589
if use_mp:
529590
try:
530591
from threading import Thread
531592
except ImportError:
532593
print "Multiprocess option requires thread support"
533594
sys.exit(2)
534-
from Queue import Queue
595+
from Queue import Queue, Empty
535596
from subprocess import Popen, PIPE
536597
debug_output_pat = re.compile(r"\[\d+ refs\]$")
537598
output = Queue()
@@ -551,63 +612,106 @@ def tests_and_args():
551612
# required to spawn a new process with PGO flag on/off
552613
if pgo:
553614
base_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
567634
popen = Popen(args,
568635
stdout=PIPE, stderr=PIPE,
569636
universal_newlines=True,
570637
close_fds=(os.name != 'nt'))
571638
stdout, stderr = popen.communicate()
572639
retcode = popen.wait()
640+
finally:
641+
self.current_test = None
573642

574-
# 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)
577646

578-
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
583652

584-
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)
587656

588-
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
592659

593-
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))
594672
for worker in workers:
595673
worker.start()
596674

675+
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+
597686
finished = 0
598687
test_index = 1
688+
get_timeout = max(PROGRESS_UPDATE, PROGRESS_MIN_TIME)
599689
try:
600690
while 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
602700
if test is None:
603701
finished += 1
604702
continue
605703
accumulate_result(test, result)
606704
if 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)
611715

612716
if stdout:
613717
print stdout
@@ -627,18 +731,22 @@ def work():
627731
for worker in workers:
628732
worker.join()
629733
else:
734+
print("Run tests sequentially")
735+
736+
previous_test = None
630737
for test_index, test in enumerate(tests, 1):
631738
if 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)
636743
if trace:
637744
# If we're tracing code coverage, then we don't exit with status
638745
# if on a false return value from main.
639746
tracer.runctx('runtest(test, verbose, quiet, testdir=testdir)',
640747
globals=globals(), locals=vars())
641748
else:
749+
start_time = time.time()
642750
try:
643751
result = runtest(test, verbose, quiet, huntrleaks, None, pgo,
644752
failfast=failfast,
@@ -655,6 +763,16 @@ def work():
655763
break
656764
except:
657765
raise
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+
658776
if findleaks:
659777
gc.collect()
660778
if gc.garbage:
@@ -683,8 +801,8 @@ def work():
683801
if print_slow:
684802
test_times.sort(reverse=True)
685803
print "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))
688806
if bad and not pgo:
689807
print count(len(bad), "test"), "failed:"
690808
printlist(bad)
@@ -745,6 +863,18 @@ def work():
745863
if runleaks:
746864
os.system("leaks %d" % os.getpid())
747865

866+
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+
748878
sys.exit(len(bad) > 0 or interrupted)
749879

750880

0 commit comments

Comments
 (0)