[New-bugs-announce] [issue38515] regrtest main process timed out after 5 min on AMD64 FreeBSD CURRENT Shared 3.8

[STINNER Victor]

New submission from STINNER Victor <vstinner at python.org>:

https://buildbot.python.org/all/#/builders/212/builds/322

=> see the traceback below.

I'm not sure that it's an issue with Python. It seems like the system was way too loaded: system load around 13.29 for 2 CPUs. I know that this buildbot worker is super slow.

The main regrtest process is supposed to write an update every 30 seconds. Timeout after 5 minutes means that the main process was either *very very slow*, or that the _get_result() method was blocked because of a real bug. I'm surprised since the code works well on all other workers. If it's a bug, one explanation would be that it's a race condition which trigger only under very precise timings.

In the main thread of the main process, the code is stuck on:

   self.output.get(timeout=30)

where self.output is a queue.Queue() instance. This line should not take longer than 30 seconds, except if the system is *really* slow.

Maybe that day, the poor AMD64 FreeBSD CURRENT Shared 3.8 was just too slow?

--

It's not the first time that I see this issue. In bpo-37531, it already failed on the same buildbot worker (koobs-freebsd-current):
https://bugs.python.org/issue37531#msg354078

When it failed, the main regrtest process used a timeout of 60 seconds. I changed this timeout to 5 minutes in commit 0ec618af98ac250a91ee9c91f8569e6df6772758.

5 minutes is already quite big. It means that the system failed to give back the CPU to regrtest main process in 5 minutes, whereas it should get the CPU after 30 seconds.

--


https://buildbot.python.org/all/#/builders/212/builds/322

...
== FreeBSD-13.0-CURRENT-amd64-64bit-ELF little-endian
== cwd: /usr/home/buildbot/python/3.8.koobs-freebsd-current/build/build/test_python_4823
== CPU count: 2
== encodings: locale=UTF-8, FS=utf-8
Using random seed 6868206
0:00:00 load avg: 9.98 Run tests in parallel using 4 child processes
0:00:05 load avg: 10.14 [  1/423] test_opcodes passed
...
0:02:12 load avg: 11.82 running: test_capi (2 min 2 sec), test_pickle (1 min 40 sec), test_multiprocessing_spawn (1 min), test_support (2 min 11 sec)
...
0:13:15 load avg: 12.41 [ 80/423] test_rlcompleter passed -- running: test_lib2to3 (1 min 7 sec), test_multiprocessing_spawn (12 min 2 sec)
...
0:13:17 load avg: 12.30 [ 81/423] test_idle skipped -- running: test_lib2to3 (1 min 9 sec), test_multiprocessing_spawn (12 min 4 sec)
...
0:39:19 load avg: 13.70 running: test_concurrent_futures (4 min 23 sec), test_codecmaps_kr (30.0 sec), test_io (5 min 14 sec), test_tokenize (7 min 20 sec)
...
0:40:53 load avg: 13.80 [208/423] test_socketserver passed -- running: test_concurrent_futures (5 min 57 sec), test_tokenize (8 min 53 sec)
0:41:16 load avg: 13.94 [209/423] test_faulthandler passed (38.2 sec) -- running: test_concurrent_futures (6 min 20 sec), test_tokenize (9 min 16 sec)
0:41:29 load avg: 13.29 [210/423] test_glob passed -- running: test_concurrent_futures (6 min 33 sec), test_zipfile (36.3 sec), test_tokenize (9 min 30 sec)
Timeout (0:05:00)!
Thread 0x000000080257c800 (most recent call first):
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/selectors.py", line 415 in select
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/subprocess.py", line 1866 in _communicate
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/subprocess.py", line 1024 in communicate
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 191 in _run_process
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 229 in _runtest
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 264 in run
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/threading.py", line 932 in _bootstrap_inner
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/threading.py", line 890 in _bootstrap

Thread 0x000000080257b900 (most recent call first):
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/selectors.py", line 415 in select
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/subprocess.py", line 1866 in _communicate
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/subprocess.py", line 1024 in communicate
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 191 in _run_process
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 229 in _runtest
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 264 in run
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/threading.py", line 932 in _bootstrap_inner
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/threading.py", line 890 in _bootstrap

Thread 0x000000080257b400 (most recent call first):
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/selectors.py", line 415 in select
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/subprocess.py", line 1866 in _communicate
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/subprocess.py", line 1024 in communicate
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 191 in _run_process
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 229 in _runtest
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 264 in run
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/threading.py", line 932 in _bootstrap_inner
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/threading.py", line 890 in _bootstrap

Thread 0x000000080257be00 (most recent call first):
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/selectors.py", line 415 in select
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/subprocess.py", line 1866 in _communicate
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/subprocess.py", line 1024 in communicate
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 191 in _run_process
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 229 in _runtest
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 264 in run
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/threading.py", line 932 in _bootstrap_inner
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/threading.py", line 890 in _bootstrap

Thread 0x0000000800ac3000 (most recent call first):
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/threading.py", line 306 in wait
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/queue.py", line 179 in get
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 372 in _get_result
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 423 in run_tests
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/runtest_mp.py", line 444 in run_tests_multiprocess
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/main.py", line 513 in run_tests
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/main.py", line 687 in _main
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/main.py", line 634 in main
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/libregrtest/main.py", line 712 in main
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/test/__main__.py", line 2 in <module>
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/runpy.py", line 85 in _run_code
  File "/usr/home/buildbot/python/3.8.koobs-freebsd-current/build/Lib/runpy.py", line 192 in _run_module_as_main
*** Error code 1

Stop.
make: stopped in /usr/home/buildbot/python/3.8.koobs-freebsd-current/build

----------
components: Tests
messages: 354875
nosy: vstinner
priority: normal
severity: normal
status: open
title: regrtest main process timed out after 5 min on AMD64 FreeBSD CURRENT Shared 3.8
versions: Python 3.9

_______________________________________
Python tracker <report at bugs.python.org>
<https://bugs.python.org/issue38515>
_______________________________________