test_concurrent_futures: reap_children() warnings on RHEL7 and RHEL8 buildbots

[vstinner]

BPO	38546
Nosy	@vstinner, @pablogsal, @miss-islington
PRs	[WIP] bpo-38546: Add support.get_child_processes() #17640 bpo-38546: multiprocessing tests stop the resource tracker #17641 [3.8] bpo-38546: multiprocessing tests stop the resource tracker (GH-17641) #17647 bpo-38546: Fix concurrent.futures test_ressources_gced_in_workers() #17652 [3.8] bpo-38546: Fix concurrent.futures test_ressources_gced_in_workers() (GH-17652) #17653 [3.7] bpo-38546: Fix concurrent.futures test_ressources_gced_in_workers() (GH-17652) #17654 [3.8] bpo-38546: Fix concurrent.futures test_ressources_gced_in_workers() (GH-17652) #17655 [3.7] bpo-38546: Fix concurrent.futures test_ressources_gced_in_workers() (GH-17652) (GH-17655) #17656 [3.7] bpo-38546: Backport multiprocessing tests fixes from master #19689

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2019-12-18.17:05:09.007>
created_at = <Date 2019-10-21.11:20:00.633>
labels = ['3.8', '3.7', 'tests', '3.9']
title = 'test_concurrent_futures: reap_children() warnings on RHEL7 and RHEL8 buildbots'
updated_at = <Date 2020-04-23.22:44:12.154>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2020-04-23.22:44:12.154>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2019-12-18.17:05:09.007>
closer = 'vstinner'
components = ['Tests']
creation = <Date 2019-10-21.11:20:00.633>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 38546
keywords = ['patch']
message_count = 19.0
messages = ['355051', '355053', '355079', '355107', '355310', '355312', '357095', '357404', '357929', '358547', '358548', '358549', '358560', '358617', '358627', '358630', '358644', '358646', '367156']
nosy_count = 3.0
nosy_names = ['vstinner', 'pablogsal', 'miss-islington']
pr_nums = ['17640', '17641', '17647', '17652', '17653', '17654', '17655', '17656', '19689']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue38546'
versions = ['Python 3.7', 'Python 3.8', 'Python 3.9']

[vstinner]

https://buildbot.python.org/all/#/builders/254/builds/162

test_no_stale_references (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.56s ok
test_ressources_gced_in_workers (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 1.90s ok
test_shutdown_race_issue12456 (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.54s ok
test_submit (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.52s ok
test_submit_keyword (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.57s ok
test_traceback (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.48s ok
test_context_manager_shutdown (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolShutdownTest) ... 0.03s ok
test_del_shutdown (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolShutdownTest) ... 0.02s ok
test_hang_issue12364 (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolShutdownTest) ... 1.45s ok
test_interpreter_shutdown (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolShutdownTest) ... 1.62s Warning -- reap_children() reaped child process 28936
ok

[vstinner]

It looks similar to bpo-38448: "test_concurrent_futures: reap_children() reaped child process 26487 on AMD64 RHEL8 Refleaks 3.x"

[vstinner]

I ran "./python -m test --fail-env-changed -w -j50 -F test_concurrent_futures" on my laptop for 5 minutes: system load of 220,57 with a peak of 403 processes... but I failed to reproduce the issue :-(

[vstinner]

The system load was at 10.02 when the bug occurred:

https://buildbot.python.org/all/#/builders/254/builds/162

...
0:04:11 load avg: 10.02 [230/419] test_pkgutil passed -- running: test_io (2 min 46 sec), test_capi (1 min 12 sec), test_concurrent_futures (2 min 43 sec), test_mailbox (2 min 40 sec), test_tokenize (30.6 sec)
0:04:12 load avg: 10.02 [231/419] test_getpass passed -- running: test_io (2 min 47 sec), test_capi (1 min 13 sec), test_concurrent_futures (2 min 43 sec), test_mailbox (2 min 41 sec), test_tokenize (31.1 sec)
0:04:12 load avg: 10.02 [232/419] test_sys passed -- running: test_io (2 min 47 sec), test_capi (1 min 13 sec), test_concurrent_futures (2 min 43 sec), test_mailbox (2 min 41 sec), test_tokenize (31.3 sec)
0:04:12 load avg: 10.02 [233/419] test_winconsoleio skipped -- running: test_io (2 min 48 sec), test_capi (1 min 13 sec), test_concurrent_futures (2 min 44 sec), test_mailbox (2 min 41 sec), test_tokenize (31.7 sec)
test_winconsoleio skipped -- test only relevant on win32
0:04:13 load avg: 10.02 [234/419/1] test_concurrent_futures failed (env changed) (2 min 44 sec) -- running: test_io (2 min 48 sec), test_capi (1 min 14 sec), test_mailbox (2 min 42 sec), test_tokenize (32.0 sec)
...
test_crash (test.test_concurrent_futures.ProcessPoolSpawnExecutorDeadlockTest) ... 4.22s ok
test_shutdown_deadlock (test.test_concurrent_futures.ProcessPoolSpawnExecutorDeadlockTest) ... 1.03s ok
test_initializer (test.test_concurrent_futures.ProcessPoolSpawnFailingInitializerTest) ... 0.51s ok
test_initializer (test.test_concurrent_futures.ProcessPoolSpawnInitializerTest) ... 0.54s ok
test_free_reference (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.67s ok
test_killed_child (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.49s ok
test_map (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.56s ok
test_map_chunksize (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.46s ok
test_map_exception (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.46s ok
test_map_timeout (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 6.48s ok
test_max_workers_negative (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.57s ok
test_max_workers_too_large (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... skipped 'Windows-only process limit'
test_no_stale_references (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.56s ok
test_ressources_gced_in_workers (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 1.90s ok
test_shutdown_race_issue12456 (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.54s ok
test_submit (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.52s ok
test_submit_keyword (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.57s ok
test_traceback (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.48s ok
test_context_manager_shutdown (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolShutdownTest) ... 0.03s ok
test_del_shutdown (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolShutdownTest) ... 0.02s ok
test_hang_issue12364 (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolShutdownTest) ... 1.45s ok
test_interpreter_shutdown (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolShutdownTest) ... 1.62s
Warning -- reap_children() reaped child process 28936
ok
test_processes_terminate (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolShutdownTest) ... 0.47s ok
test_run_after_shutdown (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolShutdownTest) ... 0.00s ok

[vstinner]

New warning on AMD64 RHEL8 LTO + PGO 3.x:
https://buildbot.python.org/all/#/builders/284/builds/171

...
test_killed_child (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.26s ok
test_map (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.29s ok
test_map_chunksize (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.31s ok
test_map_exception (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.30s ok
test_map_timeout (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 6.29s ok
test_max_workers_negative (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.32s ok
test_max_workers_too_large (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... skipped 'Windows-only process limit'
test_no_stale_references (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.29s ok
test_ressources_gced_in_workers (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 1.58s ok
test_shutdown_race_issue12456 (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.30s Warning -- reap_children() reaped child process 10340
ok
test_submit (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.29s ok
test_submit_keyword (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.31s ok
...

[vstinner]

I closed bpo-38448 as duplicate of this issue. Copy of its only message:

AMD64 RHEL8 Refleaks 3.x:
https://buildbot.python.org/all/#/builders/272/builds/23

0:27:13 load avg: 4.88 [416/419/1] test_concurrent_futures failed (env changed) (17 min 11 sec) -- running: test_capi (7 min 28 sec), test_gdb (8 min 49 sec), test_asyncio (23 min 23 sec)
beginning 6 repetitions
123456
.Warning -- reap_children() reaped child process 26487
.....
Warning -- multiprocessing.process._dangling was modified by test_concurrent_futures
Before: set()
After: {<weakref at 0x7fdc08f44e30; to 'SpawnProcess' at 0x7fdc0a467c30>}

[vstinner]

AMD64 Debian PGO 3.x:
https://buildbot.python.org/all/#/builders/47/builds/3851

test_submit_keyword (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 0.62s Warning -- reap_children() reaped child process 32627
Warning -- multiprocessing.process._dangling was modified by test_concurrent_futures

[pablogsal]

Ran 168 tests in 160.415s
OK (skipped=3)
Warning -- multiprocessing.process._dangling was modified by test_concurrent_futures
Before: set()
After: {<weakref at 0x7fd136d66540; to 'ForkProcess' at 0x7fd136cd4a90>}

Another failure in AMD64 RHEL8 LTO + PGO 3.x

https://buildbot.python.org/all/#/builders/284/builds/300/steps/5/logs/stdio

[vstinner]

New failure on AMD64 RHEL7 LTO 3.x:
https://buildbot.python.org/all/#/builders/103/builds/17

test_interpreter_shutdown
(test.test_concurrent_futures.ProcessPoolSpawnProcessPoolShutdownTest)
... 1.61s Warning -- reap_children() reaped child process 9934

[vstinner]

I managed to reproduce the issue on the RHEL8 worker using:

• terminal 1: ./python -u -m test --fail-env-changed test_concurrent_futures -v -m ProcessPoolSpawnProcessPoolExecutorTest -F -j 15
• terminal 2: ./python -m test -j4 -u all -F -r

I can still reproduce the issue with PR 17641 fix, so it's not enough.

I also applied PR 17640 and 2 extra changes:

diff --git a/Lib/multiprocessing/managers.py b/Lib/multiprocessing/managers.py
index 1f9c2daa25..dbbf84b3d2 100644
--- a/Lib/multiprocessing/managers.py
+++ b/Lib/multiprocessing/managers.py
@@ -661,7 +661,7 @@ class BaseManager(object):
             except Exception:
                 pass
 
-            process.join(timeout=1.0)
+            process.join(timeout=0.1)
             if process.is_alive():
                 util.info('manager still alive')
                 if hasattr(process, 'terminate'):
diff --git a/Lib/test/support/__init__.py b/Lib/test/support/__init__.py
index 215bab8131..110c7f945e 100644
--- a/Lib/test/support/__init__.py
+++ b/Lib/test/support/__init__.py
@@ -2399,6 +2399,7 @@ def reap_children():
 
     # Reap all our dead child processes so we don't leave zombies around.
     # These hog resources and might be causing some of the buildbots to die.
+    time.sleep(0.5)
     while True:
         try:
             # Read the exit status of any child process which already completed

[vstinner]

Example of failure, with additional debug prints:

0:01:02 load avg: 42.13 [ 38/1] test_concurrent_futures failed (env changed)
test_no_stale_references (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 2.00s reap_children
ok
test_ressources_gced_in_workers (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 3.86s reap_children
ok
test_shutdown_race_issue12456 (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 2.22s reap_children
ok
test_submit (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 2.26s reap_children
ok
test_submit_keyword (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 1.59s reap_children
ok
test_traceback (test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest) ... 1.60s reap_children
ok
MP cleanup: cleanup process
MP cleanup: stop forkserver
MP cleanup: stop res track
MP cleanup: run finalizers
reap_children

----------------------------------------------------------------------

Ran 6 tests in 17.210s

OK
reap_children
Warning -- reap_children() reaped child process 4992
Warning -- multiprocessing.process._dangling was modified by test_concurrent_futures
Before: set()
After: {<weakref at 0x7fedc87bc7d0; to 'SpawnProcess' at 0x7fedc7abcd70>}

[vstinner]

I can reproduce the issue with the following match file:

test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest.test_no_stale_references
test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest.test_ressources_gced_in_workers
test.test_concurrent_futures.ProcessPoolSpawnProcessPoolExecutorTest.test_shutdown_race_issue12456