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.

Terry, is this still an issue?  Are other Windows developers seeing this?

Yes. For 3.7 and 3.8, nothing appears until 41 seconds because test___all__ takes 40 seconds.  For 3.6, the batch result appears at 37 seconds because test___all__ runs in 36 seconds.

Terry, could you give me the full command you use to get that result?

python -m test -j0

I can't reproduce this.  Even running `python -m test -j14` on a machine with 2 vCPUs, I get my first results at 2s, and even test___all__ passes in only 6 (though on my first run, with -j0 (== -j4), test___all__ took 41s but other results came in first).  Same results with Debug and Release Win32 builds.

Ok, interesting.  The above results are from running on my Windows 8.1 buildbot, running on Azure.  Running on a local fully-updated (I think) Windows 10 VM, I get results similar to what Terry reports: results come in batches of X for -jX.  Does anyone know of any changes we've made that would cause Windows 10 to behave differently here, or has something changed in Windows itself to cause the issue?

Steve or Eryk, do you get the same?

Terry,

Do you still see this happening?  When I run the tests on Windows 10 with 12 CPUs (using -j0), the tests run quickly with just the last one taking more time.

0:01:42 [418/420] test_socket passed (40 sec 239 ms) -- running: test_multiprocessing_spawn (58 sec 500 ms)
0:01:53 [419/420] test_venv passed (32 sec 267 ms) -- running: test_multiprocessing_spawn (1 min 9 sec)
running: test_multiprocessing_spawn (1 min 39 sec)
0:02:28 [420/420] test_multiprocessing_spawn passed (1 min 44 sec)

Thanks for checking on this.  3.7.2 and 3.8.0a2 64 bit installed, as well as respository debug 32 bit 3.8.0a2+, are back to normal, with the quickest tests reporting within a few seconds.  I will assume fixed for Zach also, hence closing.