Repository navigation
[subinterpreters] test__xxsubinterpreters fails randomly #81405
Description
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 2021-07-29.17:32:05.013>
created_at = <Date 2019-06-11.00:58:01.578>
labels = ['expert-subinterpreters', 'tests', '3.9', '3.10', '3.11']
title = '[subinterpreters] test__xxsubinterpreters fails randomly'
updated_at = <Date 2021-07-29.17:32:05.010>
user = 'https://github.com/vstinner'bugs.python.org fields:
activity = <Date 2021-07-29.17:32:05.010>
actor = 'lukasz.langa'
assignee = 'none'
closed = True
closed_date = <Date 2021-07-29.17:32:05.013>
closer = 'lukasz.langa'
components = ['Tests', 'Subinterpreters']
creation = <Date 2019-06-11.00:58:01.578>
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']
Activity
vstinner commentedon Jun 11, 2019
https://buildbot.python.org/all/#/builders/224/builds/5
(...)
FAIL: test_still_running (test.test__xxsubinterpreters.DestroyTests)
----------------------------------------------------------------------
vstinner commentedon Jun 11, 2019
See bpo-33356.
vstinner commentedon Jun 11, 2019
Fail on x86 Gentoo Refleaks 3.x:
https://buildbot.python.org/all/#/builders/1/builds/618
(...)
======================================================================
FAIL: test_already_running (test.test__xxsubinterpreters.RunStringTests)
----------------------------------------------------------------------
vstinner commentedon Jun 12, 2019
Failure on AppVeyor on my PR 14029 (which is unrelated):
FAIL: test_subinterpreter (test.test__xxsubinterpreters.IsRunningTests)
----------------------------------------------------------------------
test__xxsubinterpreters passed when run again.
vstinner commentedon Jul 8, 2019
The test still fails times to times:
https://buildbot.python.org/all/#/builders/80/builds/644
FAIL: test_subinterpreter (test.test__xxsubinterpreters.IsRunningTests)
----------------------------------------------------------------------
aeros commentedon Sep 16, 2019
Upon digging through Modules/_xxsubinterpretersmodule.c, I noticed that on line 2059,
PyInterpreterState_Delete(interp);is commented out (cpython/Modules/_xxsubinterpretersmodule.c
Line 2059 in bf16991
This was done when _xxsubinterpretersmodule.c was first added by Eric Snow (
cpython/Modules/_xxsubinterpretersmodule.c
Line 2059 in bf16991
Is this because
Py_EndInterpreter()is supposed to shutdown the interpreter, soPyInterpreterState_Delete()isn't needed? If so, that still doesn't particularly explain why it was commented out. Perhaps Eric can elaborate.aeros commentedon Sep 16, 2019
Note that I'm not particularly experienced with the c-api, I'm just trying to take a stab at understanding why the buildbot failure is occuring.
aeros commentedon Sep 16, 2019
Clarification: In the above comment when I was referring to the commit made by Eric Snow, I meant to link to 7f8bfc9.
aeros commentedon Sep 16, 2019
Upon further reading of the documentation and some experimentation, it would definitely not make sense to call
PyInterpreterState_Deletehere (since we're only closing the sub-interpreter in the current thread), so that's not the issue. I still have no idea as to why it's commented out there, but that's besides the point.I think I may have found the potential cause of the test failure though. Looking into
test_still_running(), it's clear that the intention is for a RuntimeError to be raised ifinterpreters.destroy()is called on a currently running interpreter:However, within interp_destroy (
cpython/Modules/_xxsubinterpretersmodule.c
Line 2024 in 56a4514
When attempting to destroy a running interpreter, NULL is returned without raising the RuntimeError:
This was my first guess at a solution:
But, within
_ensure_not_running()(cpython/Modules/_xxsubinterpretersmodule.c
Line 1842 in 56a4514
Initially, I was unsure of the difference between
PyErr_SetString()andPyErr_Format(), so I referred to the documentation.PyErr_Format()is similar, but it also returns NULL. If I'm not mistaken doesn't mean that thereturn -1within theif (is_running)bock is effectively ignored? If so, this would potentially explain the problem...I think the appropriate solution would be to replace
PyErr_Format()withPyErr_SetString()within_ensure_not_running(). Also, I think it would be more useful to additionally raise the RuntimeError withininterp_destroy()if the interpreter is running, to provide a more useful and specific error message. "cannot destroy a running interpreter" is far more useful for debugging purposes than a more generic "interpreter already running".I plan on opening a PR to make these changes in the next few days. Let me know what you think Victor.
aeros commentedon Sep 16, 2019
Clarification:
"If I'm not mistaken doesn't mean that the
return -1within ..."Should instead be:
"If I'm not mistaken doesn't this mean that the
return -1within ..."(I am really looking forward to moving issue over to GitHub at some point. It's nice to be able to edit comments and properly format code blocks...)
aeros commentedon Sep 17, 2019
Upon further consideration, I don't think this will address the issue. If the RuntimeError was not being raised, this failure would be consistent rather than intermittent.
I think I have have gotten a bit mixed up, even if the return value of PyErr_Format is NULL, it would not implicitly return NULL upon being called and exit the function early (like a macro could) . I'm not experienced with programming in C, I only started learning it more recently (Python, Java, and C# have been my primary languages) when I started contributing to CPython in June.
Instead, I suspect this is likely a concurrency issue, where multiple threads are trying to access the same sub-interpreter during
interp_destroy(). The solution will likely involve finding the correct place for a lock. I'll continue to work on this and see if I can find a solution.aeros commentedon Sep 20, 2019
Is there a currently reliable way of accessing the GIL functions within the sub-interpreters, without causing deadlock issues? I was trying to follow the advice in the documentation (https://docs.python.org/3/c-api/init.html?highlight=global%20interpreter%20lock#bugs-and-caveats).
"It is highly recommended that you don’t switch sub-interpreters between a pair of matching PyGILState_Ensure() and PyGILState_Release() calls."
But it seemed that any attempt to use any of the PyGIL* calls within
interp_destroy()in a meaningful way resulted in a deadlock, even if it was done away from the sub-interpreter switching.My next idea would be to add a conditional check to see if the current thread has ownership of the GIL, and using
PyEval_RestoreThread()to acquire it if it doesn't. This would be followed by releasing the GIL withPyThreadState_Get()at the end of the function. I'll try experimenting with that idea next.vstinner commentedon Oct 14, 2019
I marked bpo-33356 as a duplicate of this issue:
32 remaining items
aeros commentedon Mar 12, 2020
I have a few spare cycles to take another stab at this issue. I can say with some certainty that the failure in test__xxsubinterpreters.DestroyTests does not occur on the latest commit to master (3.9):
So at this point it seems to be a matter of looking through the diff between 3.8 vs 3.9 for any relevant code paths, and attempting to determine what change resolved the failure for 3.9. It might also be useful to determine if it occurred when the tests were first added in 3.8 or if some other commit introduced a subtle regression.
[-]test__xxsubinterpreters fails randomly[/-][+][subinterpreters] test__xxsubinterpreters fails randomly[/+]koobs commentedon Jun 10, 2020
Failure on AMD64 FreeBSD Shared 3.x (full log attached):
======================================================================
FAIL: test_subinterpreter (test.test__xxsubinterpreters.IsRunningTests)
----------------------------------------------------------------------
...
2 tests failed:
test__xxsubinterpreters test_interpreters
...
...
test test_interpreters failed
test_send_recv_same_interpreter (test.test_interpreters.TestSendRecv) ... ok
======================================================================
FAIL: test_still_running (test.test_interpreters.TestInterpreterDestroy)
----------------------------------------------------------------------
======================================================================
FAIL: test_subinterpreter (test.test_interpreters.TestInterpreterIsRunning)
----------------------------------------------------------------------
======================================================================
FAIL: test_already_running (test.test_interpreters.TestInterpreterRun)
----------------------------------------------------------------------
Ran 40 tests in 20.251s
FAILED (failures=3)
1 test failed again:
test_interpreters
== Tests result: FAILURE then FAILURE ==
...
1 test failed:
test_interpreters
...
2 re-run tests:
test__xxsubinterpreters test_interpreters
vstinner commentedon Jun 29, 2020
AMD64 Windows8.1 Refleaks 3.x:
https://buildbot.python.org/all/#/builders/157/builds/218
2:51:27 load avg: 3.54 [275/423/2] test__xxsubinterpreters crashed (Exit code 3221225477) -- running: test_regrtest (2 hour 49 min), test_distutils (1 min 56 sec), test_pydoc (1 min 36 sec)
beginning 6 repetitions
123456
...Windows fatal exception: access violation
Thread 0x000004dc (most recent call first):
File "D:\buildarea\3.x.ware-win81-release.refleak\build\lib\test\test__xxsubinterpreters.py", line 766 in setUp
File "D:\buildarea\3.x.ware-win81-release.refleak\build\lib\unittest\case.py", line 547 in _callSetUp
File "D:\buildarea\3.x.ware-win81-release.refleak\build\lib\unittest\case.py", line 589 in run
File "D:\buildarea\3.x.ware-win81-release.refleak\build\lib\unittest\case.py", line 653 in __call__
(...)
vstinner commentedon Oct 1, 2020
The test still fails randomly: AMD64 Windows8.1 Refleaks 3.8
https://buildbot.python.org/all/#/builders/200/builds/48
test_subinterpreter failed twice on Refleaks which runs tests 6 times in a row.
First run:
Second run:
FAIL: test_subinterpreter (test.test__xxsubinterpreters.IsRunningTests)
----------------------------------------------------------------------
vstinner commentedon Jun 3, 2021
Recent test_still_running() failure on AMD64 Windows8.1 Refleaks 3.10:
https://buildbot.python.org/all/#/builders/638/builds/19
shihai1991 commentedon Jun 3, 2021
OK, I try to take a look after Kyle leaves temporarily. But I haven't replicate this issue in my vm in recent days :(
shihai1991 commentedon Jul 19, 2021
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)
----------------------------------------------------------------------
Ran 123 tests in 71.968s
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.