[subinterpreters] test__xxsubinterpreters fails randomly

BPO	37224
Nosy	@vstinner, @ericsnowcurrently, @koobs, @miss-islington, @shihai1991, @aeros
PRs	python/cpython#16293 python/cpython#18058 python/cpython#18318 python/cpython#26598 python/cpython#26717 python/cpython#26733 python/cpython#27240 python/cpython#27452 python/cpython#27453
Files	3.x.koobs-freebsd-564d-build-973-test-stdio.txt add_printf_to_get_details_from_race_condition.patch

^{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: ```python assignee = None closed_at = created_at = labels = ['expert-subinterpreters', 'tests', '3.9', '3.10', '3.11'] title = '[subinterpreters] test__xxsubinterpreters fails randomly' updated_at = user = 'https://github.com/vstinner' ``` bugs.python.org fields: ```python activity = actor = 'lukasz.langa' assignee = 'none' closed = True closed_date = closer = 'lukasz.langa' components = ['Tests', 'Subinterpreters'] creation = creator = 'vstinner' dependencies = [] files = ['49224', '50160'] hgrepos = [] issue_num = 37224 keywords = ['patch'] message_count = 51.0 messages = ['345162', '345163', '345219', '345415', '347486', '352508', '352509', '352510', '352514', '352516', '352592', '352835', '354658', '354659', '354661', '354662', '354677', '354876', '355221', '355520', '356631', '357347', '357349', '357350', '357361', '357364', '357365', '357378', '357671', '357672', '358358', '358359', '358373', '358552', '359699', '360024', '360025', '360027', '360029', '360209', '361130', '361353', '361354', '361387', '363992', '371160', '372561', '377749', '394974', '395021', '397809'] nosy_count = 7.0 nosy_names = ['vstinner', 'python-dev', 'eric.snow', 'koobs', 'miss-islington', 'shihai1991', 'aeros'] pr_nums = ['16293', '18058', '18318', '26598', '26717', '26733', '27240', '27452', '27453'] priority = 'normal' resolution = 'fixed' stage = 'resolved' status = 'closed' superseder = None type = None url = 'https://bugs.python.org/issue37224' versions = ['Python 3.9', 'Python 3.10', 'Python 3.11'] ```

I use this add_printf_to_get_details_from_race_condition.patch to get some details of the running subinterpreter.

The successful output of test_already_running: test_already_running (test.test__xxsubinterpreters.RunStringTests) ... In interp_create, the current state is: 0x23ee8f0 In interp_list_all, the current state is: 0x23ee8f0 # Entering _running(). Before interp runs, the current state is: 0x2489590 # Running the interp in thread. In interp_list_all, the current state is: 0x23ee8f0 # Running interpreters.list() in _running(). Before interp runs, the current state is: 0x23ee8f0 # Running the interp in test_already_running(). After interp runs, the current state is: 0x25cf0e0 # Running the interp in thread. In interp_list_all, the current state is: 0x23ee8f0 # Clearing the created interps.

The failed output of test_already_running: test_already_running (test.test__xxsubinterpreters.RunStringTests) ... In interp_create, the current state is: 0x23e58f0 In interp_list_all, the current state is: 0x23e58f0 In interp_list_all, the current state is: 0x23e58f0 # Compared to the successful output of test_already_running, the interp doesn't run in time. Before interp runs, the current state is: 0x23e58f0 spam After interp runs, the current state is: 0x24fdfc0 In interp_list_all, the current state is: 0x23e58f0 FAIL

\====================================================================== FAIL: test_already_running (test.test__xxsubinterpreters.RunStringTests) ----------------------------------------------------------------------

Traceback (most recent call last):
  File "/home/shihai/cpython/Lib/test/test__xxsubinterpreters.py", line 835, in test_already_running
    with self.assertRaises(RuntimeError):
AssertionError: RuntimeError not raised

Ran 123 tests in 71.968s

FAILED (failures=1, skipped=6)
Warning -- Uncaught thread exception: RuntimeError
Exception in thread Thread-8 (run):
Traceback (most recent call last):
  File "/home/shihai/cpython/Lib/threading.py", line 1009, in _bootstrap_inner
    self.run()
    ^^^^^^^^^^
  File "/home/shihai/cpython/Lib/threading.py", line 946, in run
    self._target(*self._args, **self._kwargs)
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/shihai/cpython/Lib/test/test__xxsubinterpreters.py", line 49, in run
    interpreters.run_string(interp, dedent(f"""
RuntimeError: unrecognized interpreter ID 60
test test__xxsubinterpreters failed.

According to above details, there are several possible explanations: 1.Some race condition break the opcode execution order. I checked the eval function. I didn't find that any condition will disrupt the execution order. 2.The running thread hasn't get the GIL in time. "RuntimeError: unrecognized interpreter ID 60" proves that the interp has been executed in _running(), but later than the test_already_running. So I creates PR 26598. But I catch the error again with PR 26598. 3.the running thread can't get the time slice of CPU. By running python with add_printf_to_get_details_from_race_condition.patch, I find that the thread created in _running() has be executed, but the interp hasn't been executed immediately in run(). At the same time, the done.set() has been executed in run(), so I guess the real reason is the thread created in _running() hasn't get the time slice of CPU to run interp in run() in multiprocess.

Pls correct me if I am wrong.

python / cpython

[subinterpreters] test__xxsubinterpreters fails randomly #81405