classification
Title: Regression in test -j behavior and time in 3.7.0b1
Type: performance Stage:
Components: Tests Versions: Python 3.8, Python 3.7
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: ncoghlan, terry.reedy, vstinner
Priority: normal Keywords:

Created on 2018-02-11 23:30 by terry.reedy, last changed 2018-02-11 23:36 by terry.reedy.

Messages (1)
msg312020 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2018-02-11 23:30
For me, on Windows, recent changes, since 3.7.0a4, have greatly reduced the benefit of j0 (= j14 on my system).  For 3.6.4 (installed), the times are around 13:30 and 2:20. The times for 3.7.0a4 (installed) are about the same parallel and would have been for serial if not for a crash.  For 3.7.0b1 and master, compiled with debug on, the times are around 24:00 and 11:10.  As shown by the increase for serial from 13:30 to 24:00, debug by itself slows tests down by nearly half.

For parallel, the slowdown from 2:20 to 11:40, is increased by an extra factor of more than 2.  The reason is that parallel tests are done in batches of n (at least on windows).  Before, a new test started in one of the 14 processes whenever the test in a process finished. All 12 cpus were kept busy until less than 12 tests remained. Now, 14 new tests are started when all the previous 14 finish.  Therefore, cpus wait while the slowest test in a batch of 14 finishes.

Beginning of old log:
Run tests in parallel using 14 child processes
0:00:00 [  1/413] test__opcode passed
0:00:00 [  2/413] test__locale passed
0:00:00 [  3/413] test__osx_support passed
0:00:00 [  4/413] test_abc passed
0:00:01 [  5/413] test_abstract_numbers passed
0:00:01 [  6/413] test_aifc passed
0:00:02 [  7/413] test_array passed
0:00:02 [  8/413] test_asdl_parser skipped
test_asdl_parser skipped -- test irrelevant for an installed Python
0:00:03 [  9/413] test_argparse passed
0:00:04 [ 10/413] test_ast passed
0:00:04 [ 11/413] test_asyncgen passed
0:00:05 [ 12/413] test_unittest passed
0:00:06 [ 13/413] test_asynchat passed
0:00:06 [ 14/413] test_atexit passed
0:00:06 [ 15/413] test_audioop passed
0:00:06 [ 16/413] test_augassign passed
0:00:07 [ 17/413] test_asyncore passed
0:00:07 [ 18/413] test_baseexception passed
0:00:07 [ 19/413] test_base64 passed
...
0:00:29 [107/413] test_enum passed
0:00:30 [108/413] test_enumerate passed
0:00:30 [109/413] test_eof passed
0:00:30 [110/413] test_epoll skipped
test_epoll skipped -- test works only on Linux 2.6
0:00:30 [111/413] test_errno passed


Beginning of new log:
Run tests in parallel using 14 child processes
running: test_grammar (30 sec), test_opcodes (30 sec), test_dict (30 sec), test_builtin (30 sec), test_exceptions (30 sec), test_types (30 sec), test_unittest (30 sec), test_doctest (30 sec), test_doctest2 (30 sec), test_support (30 sec), test___all__ (30 sec), test___future__ (30 sec), test__locale (30 sec), test__opcode (30 sec)
0:00:41 [  1/414] test_support passed -- running: test_grammar (41 sec), test_opcodes (41 sec), test_dict (41 sec), test_builtin (41 sec), test_exceptions (41 sec), test_types (41 sec), test_doctest (41 sec), test___all__ (41 sec), test___future__ (41 sec), test__locale (41 sec), test__opcode (41 sec)
0:00:41 [  2/414] test_doctest2 passed -- running: test_grammar (41 sec), test___all__ (41 sec), test__locale (41 sec)
0:00:41 [  3/414] test_unittest passed -- running: test___all__ (41 sec), test__locale (41 sec)
0:00:41 [  4/414] test__opcode passed
0:00:41 [  5/414] test_dict passed
0:00:41 [  6/414] test_types passed
0:00:41 [  7/414] test___future__ passed
0:00:41 [  8/414] test_builtin passed
0:00:41 [  9/414] test_doctest passed
0:00:41 [ 10/414] test_opcodes passed
0:00:41 [ 11/414] test_exceptions passed
0:00:41 [ 12/414] test_grammar passed
0:00:41 [ 13/414] test___all__ passed (40 sec)
0:00:41 [ 14/414] test__locale passed

The slowest test took 40 sec, and the rest of the cpus waited.

[snip list of running tests]
0:01:25 [ 15/414] test_audioop passed
0:01:25 [ 17/414] test_abstract_numbers passed
0:01:25 [ 18/414] test_abc passed
0:01:25 [ 19/414] test_aifc passed
0:01:25 [ 20/414] test_asdl_parser passed
0:01:25 [ 21/414] test_asyncgen passed
0:01:25 [ 22/414] test_atexit passed
0:01:25 [ 23/414] test_asyncio passed (42 sec)
[snip output]
0:01:25 [ 25/414] test_ast passed
0:01:25 [ 26/414] test_asynchat passed
0:01:25 [ 27/414] test_array passed
0:01:25 [ 28/414] test__osx_support passed

28 tests done in 85 seconds versus 111 in 30 seconds.
I think whatever caused this should be reversed.
History
Date User Action Args
2018-02-11 23:36:37terry.reedysetmessages: - msg312021
2018-02-11 23:36:14terry.reedysetmessages: + msg312021
2018-02-11 23:30:54terry.reedycreate