classification
Title: regrtest main process timed out after 5 min on AMD64 FreeBSD CURRENT Shared 3.8
Type: Stage: resolved
Components: Tests Versions: Python 3.9
process
Status: closed Resolution: out of date
Dependencies: Superseder:
Assigned To: Nosy List: koobs, pablogsal, vstinner
Priority: normal Keywords:

Created on 2019-10-18 11:04 by vstinner, last changed 2020-02-10 23:26 by vstinner. This issue is now closed.

Messages (4)
msg354875 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-18 11:04
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
msg354878 - (view) Author: Kubilay Kocak (koobs) (Python triager) Date: 2019-10-18 11:46
@Victor 

The guest running the worker was:

- running a FreeBSD build world (-j8)concurrently which is what was creating additional load, though I've done this before and it hasn't caused timeouts.
- suspended/resumed (virtualbox save/restore) which may have affected timings
msg354880 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-10-18 11:48
> running a FreeBSD build world (-j8)concurrently which is what was creating additional load, though I've done this before and it hasn't caused timeouts.

Maybe you should turn off the buidbot job while upgrading the system? Or try to tune process priorities?


> suspended/resumed (virtualbox save/restore) which may have affected timings

That may be another explanation, right. But it doesn't look the ideal guilty.
msg361749 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2020-02-10 23:26
I didn't see the failure recently, I close the issue.
History
Date User Action Args
2020-02-10 23:26:57vstinnersetstatus: open -> closed
resolution: out of date
messages: + msg361749

stage: resolved
2019-10-18 11:48:59vstinnersetmessages: + msg354880
2019-10-18 11:46:33koobssetmessages: + msg354878
2019-10-18 11:04:33vstinnersetnosy: + koobs, pablogsal
2019-10-18 11:04:24vstinnercreate