test_tools: test_freeze_simple_script() times out after 15 min: --with-lto --enable-optimizations (s390x LTO buildbots)

[sobolevn]

Reproduction:

1. make clean && ./configure --with-lto --enable-optimizations && make
2. ./python.exe -E ./Tools/scripts/run_tests.py -j 1 -u all -W --slowest --fail-env-changed --timeout=900 -j2 --junit-xml test-results.xml -j6 -v test_tools -m test.test_tools.test_freeze.TestFreeze.test_freeze_simple_script

Env:

• Fedora in the test suite: https://buildbot.python.org/all/#/builders/545/builds/3524
• Macos, locally

Traceback:

» ./python.exe -E  ./Tools/scripts/run_tests.py -j 1 -u all -W --slowest --fail-env-changed --timeout=900 -j2 --junit-xml test-results.xml -j6 -v test_tools
/Users/sobolev/Desktop/cpython/python.exe -u -W default -bb -E -E -m test -r -w -j 1 -u all -W --slowest --fail-env-changed --timeout=900 -j2 --junit-xml test-results.xml -j6 -v test_tools
== CPython 3.12.0a6+ (heads/main:1fd603fad2, Mar 27 2023, 09:38:01) [Clang 11.0.0 (clang-1100.0.33.16)]
== macOS-10.14.6-x86_64-i386-64bit little-endian
== Python build: release LTO+PGO
== cwd: /Users/sobolev/Desktop/cpython/build/test_python_89351æ
== CPU count: 4
== encodings: locale=UTF-8, FS=utf-8
Using random seed 5597523
0:00:00 load avg: 1.77 Run tests in parallel using 6 child processes (timeout: 15 min, worker timeout: 20 min)
0:00:30 load avg: 2.74 running: test_tools (30.0 sec)
0:01:00 load avg: 3.09 running: test_tools (1 min)
0:01:30 load avg: 2.95 running: test_tools (1 min 30 sec)
0:02:00 load avg: 3.15 running: test_tools (2 min)
0:02:30 load avg: 3.15 running: test_tools (2 min 30 sec)
0:03:00 load avg: 3.19 running: test_tools (3 min)
0:03:30 load avg: 4.23 running: test_tools (3 min 30 sec)
0:04:00 load avg: 4.75 running: test_tools (4 min)
0:04:30 load avg: 4.91 running: test_tools (4 min 30 sec)
0:05:00 load avg: 3.85 running: test_tools (5 min)
0:05:30 load avg: 4.70 running: test_tools (5 min 30 sec)
0:06:00 load avg: 4.65 running: test_tools (6 min)
0:06:30 load avg: 3.73 running: test_tools (6 min 30 sec)
0:07:00 load avg: 3.65 running: test_tools (7 min)
0:07:30 load avg: 3.33 running: test_tools (7 min 30 sec)
0:08:00 load avg: 3.28 running: test_tools (8 min)
0:08:30 load avg: 3.01 running: test_tools (8 min 30 sec)
0:09:00 load avg: 3.82 running: test_tools (9 min)
0:09:30 load avg: 4.18 running: test_tools (9 min 30 sec)
0:10:00 load avg: 3.76 running: test_tools (10 min)
0:10:30 load avg: 3.58 running: test_tools (10 min 30 sec)
0:11:00 load avg: 4.73 running: test_tools (11 min)
0:11:30 load avg: 4.45 running: test_tools (11 min 30 sec)
0:12:00 load avg: 4.22 running: test_tools (12 min)
0:12:30 load avg: 3.22 running: test_tools (12 min 30 sec)
0:13:00 load avg: 2.67 running: test_tools (13 min)
0:13:30 load avg: 4.42 running: test_tools (13 min 30 sec)
0:14:00 load avg: 4.41 running: test_tools (14 min)
0:14:30 load avg: 3.99 running: test_tools (14 min 30 sec)
0:15:00 load avg: 5.46 running: test_tools (15 min)
0:15:02 load avg: 5.46 [1/1/1] test_tools crashed (Exit code 1)
Timeout (0:15:00)!
Thread 0x0000000113c4d5c0 (most recent call first):
  File "/Users/sobolev/Desktop/cpython/Lib/selectors.py", line 415 in select
  File "/Users/sobolev/Desktop/cpython/Lib/subprocess.py", line 2075 in _communicate
  File "/Users/sobolev/Desktop/cpython/Lib/subprocess.py", line 1207 in communicate
  File "/Users/sobolev/Desktop/cpython/Lib/subprocess.py", line 550 in run
  File "/Users/sobolev/Desktop/cpython/Tools/freeze/test/freeze.py", line 25 in _run_quiet
  File "/Users/sobolev/Desktop/cpython/Tools/freeze/test/freeze.py", line 180 in prepare
  File "/Users/sobolev/Desktop/cpython/Lib/test/test_tools/test_freeze.py", line 27 in test_freeze_simple_script
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/case.py", line 579 in _callTestMethod
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/case.py", line 623 in run
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/case.py", line 678 in __call__
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 122 in run
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 122 in run
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 122 in run
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 122 in run
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 122 in run
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/runner.py", line 208 in run
  File "/Users/sobolev/Desktop/cpython/Lib/test/support/__init__.py", line 1106 in _run_suite
  File "/Users/sobolev/Desktop/cpython/Lib/test/support/__init__.py", line 1232 in run_unittest
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/runtest.py", line 281 in _test_module
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/runtest.py", line 317 in _runtest_inner2
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/runtest.py", line 360 in _runtest_inner
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/runtest.py", line 219 in _runtest
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/runtest.py", line 265 in runtest
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/runtest_mp.py", line 98 in run_tests_worker
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/main.py", line 732 in _main
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/main.py", line 711 in main
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/main.py", line 775 in main
  File "/Users/sobolev/Desktop/cpython/Lib/test/regrtest.py", line 43 in _main
  File "/Users/sobolev/Desktop/cpython/Lib/test/regrtest.py", line 47 in <module>
  File "<frozen runpy>", line 88 in _run_code
  File "<frozen runpy>", line 198 in _run_module_as_main

== Tests result: FAILURE ==

10 slowest tests:

1 test failed:
    test_tools
0:15:02 load avg: 5.46
0:15:02 load avg: 5.46 Re-running failed tests in verbose mode
0:15:02 load avg: 5.46 Re-running test_tools in verbose mode
test_freeze_simple_script (test.test_tools.test_freeze.TestFreeze.test_freeze_simple_script) ... Timeout (0:15:00)!
Thread 0x000000010b8a55c0 (most recent call first):
  File "/Users/sobolev/Desktop/cpython/Lib/selectors.py", line 415 in select
  File "/Users/sobolev/Desktop/cpython/Lib/subprocess.py", line 2075 in _communicate
  File "/Users/sobolev/Desktop/cpython/Lib/subprocess.py", line 1207 in communicate
  File "/Users/sobolev/Desktop/cpython/Lib/subprocess.py", line 550 in run
  File "/Users/sobolev/Desktop/cpython/Tools/freeze/test/freeze.py", line 25 in _run_quiet
  File "/Users/sobolev/Desktop/cpython/Tools/freeze/test/freeze.py", line 180 in prepare
  File "/Users/sobolev/Desktop/cpython/Lib/test/test_tools/test_freeze.py", line 27 in test_freeze_simple_script
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/case.py", line 579 in _callTestMethod
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/case.py", line 623 in run
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/case.py", line 678 in __call__
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 122 in run
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 122 in run
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 122 in run
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 122 in run
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 122 in run
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/sobolev/Desktop/cpython/Lib/unittest/runner.py", line 208 in run
  File "/Users/sobolev/Desktop/cpython/Lib/test/support/__init__.py", line 1106 in _run_suite
  File "/Users/sobolev/Desktop/cpython/Lib/test/support/__init__.py", line 1232 in run_unittest
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/runtest.py", line 281 in _test_module
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/runtest.py", line 317 in _runtest_inner2
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/runtest.py", line 360 in _runtest_inner
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/runtest.py", line 235 in _runtest
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/runtest.py", line 265 in runtest
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/main.py", line 353 in rerun_failed_tests
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/main.py", line 756 in _main
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/main.py", line 711 in main
  File "/Users/sobolev/Desktop/cpython/Lib/test/libregrtest/main.py", line 775 in main
  File "/Users/sobolev/Desktop/cpython/Lib/test/__main__.py", line 2 in <module>
  File "<frozen runpy>", line 88 in _run_code
  File "<frozen runpy>", line 198 in _run_module_as_main

Looks like timeout is killing this test. I tried to increase it, it helped:

» ./python.exe -E  ./Tools/scripts/run_tests.py -j 1 -u all -W --slowest --fail-env-changed --timeout=1800 -j2 --junit-xml test-results.xml -j6 -v test_tools -m test.test_tools.test_freeze.TestFreeze.test_freeze_simple_script
/Users/sobolev/Desktop/cpython/python.exe -u -W default -bb -E -E -m test -r -w -j 1 -u all -W --slowest --fail-env-changed --timeout=1800 -j2 --junit-xml test-results.xml -j6 -v test_tools -m test.test_tools.test_freeze.TestFreeze.test_freeze_simple_script
== CPython 3.12.0a6+ (heads/main:1fd603fad2, Mar 27 2023, 09:38:01) [Clang 11.0.0 (clang-1100.0.33.16)]
== macOS-10.14.6-x86_64-i386-64bit little-endian
== Python build: release LTO+PGO
== cwd: /Users/sobolev/Desktop/cpython/build/test_python_39615æ
== CPU count: 4
== encodings: locale=UTF-8, FS=utf-8
Using random seed 1597906
0:00:00 load avg: 2.79 Run tests in parallel using 6 child processes (timeout: 30 min, worker timeout: 35 min)
0:01:00 load avg: 3.25 running: test_tools (1 min)
0:01:30 load avg: 3.33 running: test_tools (1 min 30 sec)
0:02:00 load avg: 3.41 running: test_tools (2 min)
0:02:30 load avg: 3.59 running: test_tools (2 min 30 sec)
0:03:00 load avg: 3.33 running: test_tools (3 min)
0:03:30 load avg: 3.43 running: test_tools (3 min 30 sec)
0:04:00 load avg: 3.08 running: test_tools (4 min)
0:04:30 load avg: 2.80 running: test_tools (4 min 30 sec)
0:05:00 load avg: 5.62 running: test_tools (5 min)
0:05:30 load avg: 5.53 running: test_tools (5 min 30 sec)
0:06:00 load avg: 4.24 running: test_tools (6 min)
0:06:30 load avg: 3.55 running: test_tools (6 min 30 sec)
0:07:00 load avg: 4.57 running: test_tools (7 min)
0:07:30 load avg: 4.09 running: test_tools (7 min 30 sec)
0:08:00 load avg: 3.80 running: test_tools (8 min)
0:08:30 load avg: 4.14 running: test_tools (8 min 30 sec)
0:09:00 load avg: 7.55 running: test_tools (9 min)
0:09:30 load avg: 7.24 running: test_tools (9 min 30 sec)
0:10:00 load avg: 5.84 running: test_tools (10 min)
0:10:30 load avg: 4.38 running: test_tools (10 min 30 sec)
0:11:00 load avg: 4.52 running: test_tools (11 min)
0:11:30 load avg: 4.17 running: test_tools (11 min 30 sec)
0:12:00 load avg: 4.23 running: test_tools (12 min)
0:12:30 load avg: 4.35 running: test_tools (12 min 30 sec)
0:13:00 load avg: 4.11 running: test_tools (13 min)
0:13:30 load avg: 3.37 running: test_tools (13 min 30 sec)
0:14:00 load avg: 3.12 running: test_tools (14 min)
0:14:30 load avg: 3.73 running: test_tools (14 min 30 sec)
0:15:00 load avg: 3.18 running: test_tools (15 min)
0:15:30 load avg: 2.94 running: test_tools (15 min 30 sec)
0:16:00 load avg: 4.23 running: test_tools (16 min)
0:16:30 load avg: 4.90 running: test_tools (16 min 30 sec)
0:17:00 load avg: 4.58 running: test_tools (17 min)
0:17:30 load avg: 4.44 running: test_tools (17 min 30 sec)
0:18:00 load avg: 5.53 running: test_tools (18 min)
0:18:30 load avg: 4.19 running: test_tools (18 min 30 sec)
0:19:00 load avg: 3.39 running: test_tools (19 min)
0:19:30 load avg: 2.78 running: test_tools (19 min 30 sec)
0:19:55 load avg: 2.72 [1/1] test_tools passed (19 min 55 sec)

== Tests result: SUCCESS ==

1 test OK.

10 slowest tests:
- test_tools: 19 min 55 sec

Total duration: 19 min 55 sec
Tests result: SUCCESS

So, should be increase this timeout in CI? Or should we try optimizing this test somehow?

Linked PRs

• gh-103053: Skip the whole test_freeze module in tests on s390x with PGO #103170
• gh-103053: Skip test_freeze_simple_script() on PGO build #109591
• [3.12] gh-103053: Skip test_freeze_simple_script() on PGO build (#109591) #109614
• [3.11] gh-103053: Skip test_freeze_simple_script() on PGO build (#109591) #109616
• gh-103053: Run tools test_freeze on buildbot #110075
• gh-103053: Run tools test_freeze on buildbot (second attempt) #110447
• gh-103053: Fix BUILDPYTHON target of Makefile #110448
• gh-103053: Fix make check-clean-src: check "python" program #110449
• gh-103053: Fix test_tools.test_freeze on FreeBSD #110451
• [3.12] gh-103053: Fix make check-clean-src: check "python" program (GH-110449) #110453
• [3.11] gh-103053: Fix make check-clean-src: check "python" program (GH-110449) #110454
• [3.12] gh-103053: Fix test_tools.test_freeze on FreeBSD (GH-110451) #110456
• [3.11] gh-103053: Fix test_tools.test_freeze on FreeBSD (GH-110451) #110457
• gh-103053: Run tools test_freeze on buildbot #110458

[sobolevn]

CC @kumaraditya303 as freeze expert

[kumaraditya303]

Let's first increase the timeout to unblock the CI and then think about improving the test.

@sobolevn Can you send a PR for it?

[sobolevn]

One moment, I think I found something interesting. Right now it has this decorator:

@support.skip_if_buildbot('not all buildbots have enough space')
class TestFreeze(unittest.TestCase):

    def test_freeze_simple_script(self): ...

It was introduced in #29222 by @ericsnowcurrently

I think that it should not be tested in buildbots at all!
Let's take some recent commit (361a3ea) and examine it:

• s390x Fedora LTO + PGO 3.x is failing: https://buildbot.python.org/all/#/builders/545/builds/3541 because of this test
• All others do pass saying 0:03:50 load avg: 0.65 [163/433] test_tools passed

But, since we only skip a test case, not all file - it won't be reported anyway.

So, my guess is: maybe s390x Fedora LTO + PGO 3.x is not configured properly?
It looks like skip_if_buildbot does not work for this exact worker.

I will try to run this test explicitly with module-level skip and I hope I will be able to find the problem.

[sobolevn]

First failure that I was able to find: c3a1783

CC @erlend-aasland

[erlend-aasland]

@sobolevn, does gh-103213 fix this issue?

[sobolevn]

I would be able to check next week, I have a conference to make right now :(

[erlend-aasland]

No worries; enjoy the conference :)

[mcepl]

I don’t see much difference (Python 3.11.3 on openSUSE/Tumbleweed):

[ 2235s] ======================================================================
[ 2235s] ERROR: test_freeze_simple_script (test.test_tools.test_freeze.TestFreeze.test_freeze_simple_script)
[ 2235s] ----------------------------------------------------------------------
[ 2235s] Traceback (most recent call last):
[ 2235s]   File "/home/abuild/rpmbuild/BUILD/Python-3.11.3/Lib/test/test_tools/test_freeze.py", line 27, in test_freeze_simple_script
[ 2235s]     outdir, scriptfile, python = helper.prepare(script, outdir)
[ 2235s]                                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[ 2235s]   File "/home/abuild/rpmbuild/BUILD/Python-3.11.3/Tools/freeze/test/freeze.py", line 183, in prepare
[ 2235s]     _run_quiet([MAKE, '-C', builddir, 'install'])
[ 2235s]   File "/home/abuild/rpmbuild/BUILD/Python-3.11.3/Tools/freeze/test/freeze.py", line 25, in _run_quiet
[ 2235s]     return subprocess.run(
[ 2235s]            ^^^^^^^^^^^^^^^
[ 2235s]   File "/home/abuild/rpmbuild/BUILD/Python-3.11.3/Lib/subprocess.py", line 571, in run
[ 2235s]     raise CalledProcessError(retcode, process.args,
[ 2235s] subprocess.CalledProcessError: Command '['/usr/bin/make', '-C', '/tmp/tmpwh6sh465/python-build', 'install']' returned non-zero exit status 2.
[ 2235s] 
[ 2235s] ----------------------------------------------------------------------

Complete build log

[mcepl]

Isn’t the solution to extend

cpython/Lib/test/support/__init__.py

Line 396 in 5b05b01

isbuildbot = getpass.getuser().lower() == 'buildbot'

to cover other build environments? For me (at openSUSE with our build environment) it was enough just to add this patch:

--- a/Lib/test/support/__init__.py
+++ b/Lib/test/support/__init__.py
@@ -388,7 +388,7 @@ def skip_if_buildbot(reason=None):
     if not reason:
         reason = 'not suitable for buildbots'
     try:
-        isbuildbot = getpass.getuser().lower() == 'buildbot'
+        isbuildbot = getpass.getuser().lower() in ['buildbot', 'abuild']
     except (KeyError, EnvironmentError) as err:
         warnings.warn(f'getpass.getuser() failed {err}.', RuntimeWarning)
         isbuildbot = False

If those tests are problematic in the buildbot here, why to expect they won’t fail in other limited build environments, so extending the list of those seems legitimate.