Title: Reduce the time test_subprocess takes to complete.
Type: performance Stage: patch review
Components: Tests Versions: Python 3.9
Status: open Resolution:
Dependencies: Superseder:
Assigned To: gregory.p.smith Nosy List: gregory.p.smith, pablogsal, vstinner
Priority: low Keywords: patch

Created on 2019-10-12 21:27 by gregory.p.smith, last changed 2020-10-20 17:33 by gregory.p.smith.

Pull Requests
URL Status Linked Edit
PR 16736 merged gregory.p.smith, 2019-10-12 21:33
PR 16737 merged gregory.p.smith, 2019-10-12 23:42
PR 16739 merged pablogsal, 2019-10-13 01:09
Messages (8)
msg354554 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2019-10-12 21:27
test_subprocess is one of our long running tests, this slows down CI and buildbots.  There is room for improvement in its total execution time.

Use this issue as a rollup issue for any such work.  we need to keep it reliable, just focus on reducing either user/sys cpu time or wall time.
msg354557 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2019-10-12 23:35
New changeset 67b93f80c764bca01c81c989d74a99df208bea4d by Gregory P. Smith in branch 'master':
bpo-38456: Use /bin/true in test_subprocess (GH-16736)
msg354563 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2019-10-13 01:40
New changeset 46113e0cf32748f66cf64cd633984d143b433cd1 by Pablo Galindo in branch 'master':
bpo-38456: Handle the case when there is no 'true' command (GH-16739)
msg354648 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2019-10-14 20:40
New changeset 4f0587f161786318cdfa22c42459676fa42aacb6 by Gregory P. Smith in branch '3.8':
[3.8] bpo-38456: Use /bin/true in test_subprocess (GH-16737)
msg354649 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-14 20:48
Nice. Any idea of the speedup on Travis CI and/or on a specific buildbot worker?
msg354651 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2019-10-14 21:00
I assume the CI systems are shared and potentially noisy.  It should be easier to look at some logs from slower buildbots.  but sadly test_subprocess has fallen off the list of "10 slowest tests" that timing info is supplied for.  concurrent.futures, multiprocessing, asyncio, tokenize, etc. all take longer.

I still don't expect it to be more than a few seconds.
msg379077 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2020-10-20 02:26
the slowest tests on Linux today (with number of seconds prepended on my system that runs the suite serially in 34 seconds on a debug build):

3.01 test_check_output_stdout_arg (test.test_subprocess.ProcessTestCaseNoPoll) ... ok
3.01 test_check_output_stdout_arg (test.test_subprocess.ProcessTestCase) ... ok
3.0 test_check_output_stdin_with_input_arg (test.test_subprocess.RunFuncTestCase) ... ok
2.28 test_issue8780 (test.test_subprocess.ProcessTestCase) ... ok
2.27 test_issue8780 (test.test_subprocess.ProcessTestCaseNoPoll) ... ok
2.04 test_communicate_BrokenPipeError_stdin_write (test.test_subprocess.POSIXProcessTestCase) ... ok
1.45 test_leak_fast_process_del_killed (test.test_subprocess.POSIXProcessTestCase) ... ok
1.04 test_communicate_stdout (test.test_subprocess.ProcessTestCase) ... ok
1.03 test_communicate_stdout (test.test_subprocess.ProcessTestCaseNoPoll) ... ok
1.03 test_kill (test.test_subprocess.POSIXProcessTestCase) ... ok
1.03 test_send_signal (test.test_subprocess.POSIXProcessTestCase) ... ok
1.03 test_terminate (test.test_subprocess.POSIXProcessTestCase) ... ok
0.636 test_communicate_timeout (test.test_subprocess.ProcessTestCase) ... ok
0.636 test_communicate_timeout (test.test_subprocess.ProcessTestCaseNoPoll) ... ok
0.58 test_swap_fds (test.test_subprocess.POSIXProcessTestCase) ... ok
msg379147 - (view) Author: Gregory P. Smith (gregory.p.smith) * (Python committer) Date: 2020-10-20 17:33
fyi - handy command to get that

python -m test.regrtest -v test_subprocess | ts '.%s'

then process that using whatever you want to compute deltas and sort.  i fed the output of that into:

"""Parse `python -m test.regrtest -v | ts '.%s'` output, report slowest."""

import sys
from typing import Sequence, Tuple

infile = sys.stdin

deltas: Sequence[Tuple[float, str]] = []

prev_secs: float = 0.
prev_test: str = ''
for line in infile:
  stripped_line = line.strip()
  if ' ' not in stripped_line:
  num, test = stripped_line.split(None, 1)
  secs = float(num)
  delta = secs - prev_secs if prev_secs else 0.
  if '... ok' or '... skipped' in test:  # Not extraneous output.
    # Assign the accumulated time to the previous test.
    deltas.append((delta, prev_test))
    prev_secs = secs
    prev_test = test

for secs, test in reversed(sorted(deltas, key=lambda x:x[0])[-23:]):
  print(f'{secs:.3} {test}')
Date User Action Args
2020-10-20 17:33:23gregory.p.smithsetmessages: + msg379147
2020-10-20 02:26:15gregory.p.smithsetmessages: + msg379077
2019-10-14 21:00:19gregory.p.smithsetmessages: + msg354651
2019-10-14 20:48:42vstinnersetnosy: + vstinner
messages: + msg354649
2019-10-14 20:40:36gregory.p.smithsetmessages: + msg354648
2019-10-13 01:40:27pablogsalsetnosy: + pablogsal
messages: + msg354563
2019-10-13 01:09:52pablogsalsetpull_requests: + pull_request16318
2019-10-12 23:42:13gregory.p.smithsetpull_requests: + pull_request16316
2019-10-12 23:35:56gregory.p.smithsetmessages: + msg354557
2019-10-12 21:33:54gregory.p.smithsetkeywords: + patch
stage: patch review
pull_requests: + pull_request16315
2019-10-12 21:27:44gregory.p.smithcreate