René's URL Explorer Experiment

{"@context":"https://schema.org","@type":"DiscussionForumPosting","headline":"Deadlock in threaded application when using `sys._current_frames`","articleBody":"# Bug report\r\n\r\nWhen using `sys._current_frames` in a threaded application there is a high risk of a deadlock in the interpreter. Below is my analysis from one such hang. We have never seen this problem with Python 3.8 but experience it regularly with Python 3.11. I know that the `sys._current_frames` documentation warns about the function and one solution to this bug report could be to document that the function is not thread safe.\r\n\r\nWe have a huge number of threads in this application but I'll limit the output to the two threads that cause the deadlock.\r\n\r\nWe have a thread calling `sys._current_frames` with a Python stack trace:\r\n\r\n```\r\nThread 118868 (idle): \"Profile\"\r\n    _gc_callback (distributed/utils_perf.py:184)\r\n    _watch (distributed/profile.py:261)\r\n    run (threading.py:975)\r\n    _bootstrap_inner (threading.py:1038)\r\n    _bootstrap (threading.py:995)\r\n```\r\n\r\nand a corresponding C stack trace:\r\n\r\n```\r\nThread 325 (Thread 0x7f8b992d6700 (LWP 118868) \"\"):\r\n#0  0x00007f8ce83adde2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0\r\n#1  0x00000000004eae32 in PyCOND_TIMEDWAIT (us=\u003coptimized out\u003e, mut=\u003coptimized out\u003e, cond=0x879128 \u003c_PyRuntime+392\u003e) at /usr/local/src/conda/python-3.11.4/Python/condvar.h:73\r\n#2  take_gil (tstate=0x7f8b992d54e0) at /usr/local/src/conda/python-3.11.4/Python/ceval_gil.h:250\r\n#3  0x00000000005134bc in eval_frame_handle_pending (tstate=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Python/ceval.c:1211\r\n#4  _PyEval_EvalFrameDefault (tstate=\u003coptimized out\u003e, frame=\u003coptimized out\u003e, throwflag=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Python/ceval.c:1754\r\n#5  0x000000000055451f in _PyEval_EvalFrame (throwflag=0, frame=0x7f8bb645e248, tstate=0x5c60c20) at /usr/local/src/conda/python-3.11.4/Include/internal/pycore_ceval.h:73                                                                    #6  _PyEval_Vector (kwnames=\u003coptimized out\u003e, argcount=\u003coptimized out\u003e, args=\u003coptimized out\u003e, locals=0x0, func=0x7f8cdc1d2340, tstate=0x5c60c20) at /usr/local/src/conda/python-3.11.4/Python/ceval.c:6439\r\n#7  _PyFunction_Vectorcall (kwnames=\u003coptimized out\u003e, nargsf=\u003coptimized out\u003e, stack=\u003coptimized out\u003e, func=\u003cfunction at remote 0x7f8cdc1d2340\u003e) at /usr/local/src/conda/python-3.11.4/Objects/call.c:393\r\n#8  _PyObject_VectorcallTstate (tstate=0x5c60c20, callable=\u003cfunction at remote 0x7f8cdc1d2340\u003e, args=\u003coptimized out\u003e, nargsf=\u003coptimized out\u003e, kwnames=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Include/internal/pycore_call.h:92#9  0x0000000000554172 in method_vectorcall (method=method@entry=\u003cmethod at remote 0x7f8bce070c00\u003e, args=args@entry=0x7f8b992d57d0, nargsf=\u003coptimized out\u003e, kwnames=kwnames@entry=0x0) at /usr/local/src/conda/python-3.11.4/Objects/classobject.c:89\r\n#10 0x00000000004fe378 in _PyObject_VectorcallTstate (kwnames=0x0, nargsf=\u003coptimized out\u003e, args=0x7f8b992d57d0, callable=\u003cmethod at remote 0x7f8bce070c00\u003e, tstate=0x5c60c20) at /usr/local/src/conda/python-3.11.4/Include/internal/pycore_call.h:92\r\n#11 _PyObject_CallFunctionVa (is_size_t=0, va=0x7f8b992d57b0, format=\u003coptimized out\u003e, callable=\u003cmethod at remote 0x7f8bce070c00\u003e, tstate=0x5c60c20) at /usr/local/src/conda/python-3.11.4/Objects/call.c:536\r\n#12 PyObject_CallFunction (callable=\u003cmethod at remote 0x7f8bce070c00\u003e, format=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Objects/call.c:558\r\n#13 0x00000000005c23d2 in invoke_gc_callback (phase=0x654129 \"stop\", generation=\u003coptimized out\u003e, collected=\u003coptimized out\u003e, uncollectable=\u003coptimized out\u003e, tstate=\u003coptimized out\u003e, tstate=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Modules/gcmodule.c:1378\r\n#14 0x00000000005c230a in gc_collect_with_callback (tstate=0x5c60c20, generation=0) at /usr/local/src/conda/python-3.11.4/Modules/gcmodule.c:1401\r\n#15 0x000000000053b418 in _PyObject_GC_Link (op=set()) at /usr/local/src/conda/python-3.11.4/Modules/gcmodule.c:2270\r\n#16 gc_alloc (presize=\u003coptimized out\u003e, basicsize=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Modules/gcmodule.c:2290\r\n#17 _PyObject_GC_NewVar (nitems=\u003coptimized out\u003e, tp=0x869fe0 \u003cPyFrame_Type\u003e) at /usr/local/src/conda/python-3.11.4/Modules/gcmodule.c:2318\r\n#18 _PyFrame_New_NoTrack (code=\u003coptimized out\u003e, code=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Objects/frameobject.c:1024\r\n#19 _PyFrame_MakeAndSetFrameObject (frame=0x7f8b90e95a68) at /usr/local/src/conda/python-3.11.4/Python/frame.c:33\r\n#20 0x00000000004e19df in _PyFrame_GetFrameObject (frame=0x7f8b90e95a68) at /usr/local/src/conda/python-3.11.4/Include/internal/pycore_frame.h:171                                                                                            #21 _PyThread_CurrentFrames () at /usr/local/src/conda/python-3.11.4/Python/pystate.c:1420\r\n#22 0x00000000005061c1 in cfunction_vectorcall_NOARGS (func=\u003cbuilt-in method _current_frames of module object at remote 0x7f8ce8746ca0\u003e, args=\u003coptimized out\u003e, nargsf=\u003coptimized out\u003e, kwnames=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Include/cpython/methodobject.h:52\r\n#23 0x000000000051bde1 in _PyObject_VectorcallTstate (kwnames=\u003coptimized out\u003e, nargsf=\u003coptimized out\u003e, args=\u003coptimized out\u003e, callable=\u003cbuilt-in method _current_frames of module object at remote 0x7f8ce8746ca0\u003e, tstate=0x5c60c20) at /usr/local/src/conda/python-3.11.4/Include/internal/pycore_call.h:92\r\n#24 PyObject_Vectorcall (callable=\u003cbuilt-in method _current_frames of module object at remote 0x7f8ce8746ca0\u003e, args=\u003coptimized out\u003e, nargsf=\u003coptimized out\u003e, kwnames=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Objects/call.c:299\r\n#25 0x000000000050ed83 in _PyEval_EvalFrameDefault (tstate=\u003coptimized out\u003e, frame=\u003coptimized out\u003e, throwflag=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Python/ceval.c:4774\r\n#26 0x0000000000534f13 in _PyEval_EvalFrame (throwflag=0, frame=0x7f8bb645e188, tstate=0x5c60c20) at /usr/local/src/conda/python-3.11.4/Include/internal/pycore_ceval.h:73\r\n#27 _PyEval_Vector (kwnames=\u003coptimized out\u003e, argcount=0, args=0x7f8bce07e978, locals=0x0, func=\u003coptimized out\u003e, tstate=0x5c60c20) at /usr/local/src/conda/python-3.11.4/Python/ceval.c:6439 \r\n#28 _PyFunction_Vectorcall (func=\u003coptimized out\u003e, stack=0x7f8bce07e978, nargsf=\u003coptimized out\u003e, kwnames=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Objects/call.c:393\r\n#29 0x000000000053ef0d in _PyVectorcall_Call (kwargs=\u003coptimized out\u003e, tuple=\u003coptimized out\u003e, callable=\u003cfunction at remote 0x7f8cdc121800\u003e, func=0x534da0 \u003c_PyFunction_Vectorcall\u003e, tstate=0x5c60c20) at /usr/local/src/conda/python-3.11.4/Objects/call.c:257\r\n#30 _PyObject_Call (kwargs=\u003coptimized out\u003e, args=\u003coptimized out\u003e, callable=\u003cfunction at remote 0x7f8cdc121800\u003e, tstate=0x5c60c20) at /usr/local/src/conda/python-3.11.4/Objects/call.c:328\r\n#31 PyObject_Call (callable=\u003cfunction at remote 0x7f8cdc121800\u003e, args=\u003coptimized out\u003e, kwargs=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Objects/call.c:355\r\n#32 0x000000000051290a in do_call_core (use_tracing=\u003coptimized out\u003e, kwdict={'thread_id': 140243172636480, 'interval': '10ms', 'cycle': '1000ms', 'log': \u003ccollections.deque at remote 0x7f8bc008b1f0\u003e, 'omit': ('profile.py', 'selectors.py'), 'stop': \u003cfunction at remote 0x7f8bc0058220\u003e}, callargs=(), func=\u003cfunction at remote 0x7f8cdc121800\u003e, tstate=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Python/ceval.c:7357\r\n#33 _PyEval_EvalFrameDefault (tstate=\u003coptimized out\u003e, frame=\u003coptimized out\u003e, throwflag=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Python/ceval.c:5381\r\n#34 0x000000000055451f in _PyEval_EvalFrame (throwflag=0, frame=0x7f8bb645e020, tstate=0x5c60c20) at /usr/local/src/conda/python-3.11.4/Include/internal/pycore_ceval.h:73\r\n#35 _PyEval_Vector (kwnames=\u003coptimized out\u003e, argcount=\u003coptimized out\u003e, args=\u003coptimized out\u003e, locals=0x0, func=0x7f8ce0e41b20, tstate=0x5c60c20) at /usr/local/src/conda/python-3.11.4/Python/ceval.c:6439\r\n#36 _PyFunction_Vectorcall (kwnames=\u003coptimized out\u003e, nargsf=\u003coptimized out\u003e, stack=\u003coptimized out\u003e, func=\u003cfunction at remote 0x7f8ce0e41b20\u003e) at /usr/local/src/conda/python-3.11.4/Objects/call.c:393\r\n#37 _PyObject_VectorcallTstate (tstate=0x5c60c20, callable=\u003cfunction at remote 0x7f8ce0e41b20\u003e, args=\u003coptimized out\u003e, nargsf=\u003coptimized out\u003e, kwnames=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Include/internal/pycore_call.h:92\r\n#38 0x00000000005541f8 in method_vectorcall (method=\u003coptimized out\u003e, args=0x8875d0 \u003c_PyRuntime+58928\u003e, nargsf=\u003coptimized out\u003e, kwnames=0x0) at /usr/local/src/conda/python-3.11.4/Objects/classobject.c:67 \r\n#39 0x0000000000627f6f in thread_run (boot_raw=0x7f8cc9c987b0) at /usr/local/src/conda/python-3.11.4/Modules/_threadmodule.c:1092\r\n#40 0x00000000005f63d4 in pythread_wrapper (arg=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Python/thread_pthread.h:241\r\n#41 0x00007f8ce83a9ea5 in start_thread () from /lib64/libpthread.so.0\r\n#42 0x00007f8ce79c9b0d in clone () from /lib64/libc.so.6\r\n```\r\n\r\nSo, this thread does not hold the GIL but seems to hold the `runtime-\u003einterpreters.mutex`\r\n\r\nWe have another thread that seems to hold the GIL:\r\n\r\n```\r\nThread 388 (Thread 0x7f8b62f7f700 (LWP 120217) \"\"):\r\n#0  0x00007f8ce83afb3b in do_futex_wait.constprop () from /lib64/libpthread.so.0\r\n#1  0x00007f8ce83afbcf in __new_sem_wait_slow.constprop.0 () from /lib64/libpthread.so.0\r\n#2  0x00007f8ce83afc6b in sem_wait@@GLIBC_2.2.5 () from /lib64/libpthread.so.0                                                                                                                                                                #3  0x00000000004ea969 in PyThread_acquire_lock_timed (intr_flag=\u003coptimized out\u003e, microseconds=\u003coptimized out\u003e, lock=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Python/thread_pthread.h:497\r\n#4  PyThread_acquire_lock (lock=0x18bd040, waitflag=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Python/thread_pthread.h:751\r\n#5  0x00000000005f7266 in tstate_delete_common (tstate=0x7f8cc417c250, gilstate=0x8791d8 \u003c_PyRuntime+568\u003e) at /usr/local/src/conda/python-3.11.4/Python/pystate.c:1080\r\n#6  0x00000000005f6d93 in _PyThreadState_DeleteCurrent (tstate=0x7f8cc417c250) at /usr/local/src/conda/python-3.11.4/Python/pystate.c:1132\r\n#7  0x00000000005f63d4 in pythread_wrapper (arg=\u003coptimized out\u003e) at /usr/local/src/conda/python-3.11.4/Python/thread_pthread.h:241\r\n#8  0x00007f8ce83a9ea5 in start_thread () from /lib64/libpthread.so.0\r\n#9  0x00007f8ce79c9b0d in clone () from /lib64/libc.so.6\r\n```\r\n\r\nSee the `native_thread_id` in the following gdb output.\r\n\r\n```\r\n(gdb) p *PyThreadState_Get()\r\n$10 = {prev = 0x7f8cc4269680, next = 0x7f8c94483340, interp = 0x8875d8 \u003c_PyRuntime+58936\u003e, _initialized = 1, _static = 0, recursion_remaining = 1000, recursion_limit = 1000, recursion_headroom = 0, tracing = 0, tracing_what = 0, \r\n  cframe = 0x7f8cc417c3a0, c_profilefunc = 0x0, c_tracefunc = 0x0, c_profileobj = 0x0, c_traceobj = 0x0, curexc_type = 0x0, curexc_value = 0x0, curexc_traceback = 0x0, exc_info = 0x7f8cc417c390, dict = 0x0, gilstate_counter = 1, \r\n  async_exc = 0x0, thread_id = 140236637599488, native_thread_id = 120217, trash_delete_nesting = 0, trash_delete_later = 0x0, on_delete = 0x628f10 \u003crelease_sentinel\u003e, on_delete_data = 0x7f8b974b1ee0, \r\n  coroutine_origin_tracking_depth = 0, async_gen_firstiter = 0x0, async_gen_finalizer = 0x0, context = 0x0, context_ver = 1, id = 1085, trace_info = {code = 0x0, bounds = {ar_start = 0, ar_end = 0, ar_line = 0, opaque = {\r\n        computed_line = 0, lo_next = 0x0, limit = 0x0}}}, datastack_chunk = 0x7f8b99522000, datastack_top = 0x7f8b99522020, datastack_limit = 0x7f8b99526000, exc_state = {exc_value = 0x0, previous_item = 0x0}, root_cframe = {\r\n    use_tracing = 0 '\\000', current_frame = 0x0, previous = 0x0}}\r\n```\r\n\r\n# Your environment\r\n\r\nPython 3.11.4 on a CentOS 7 machine with conda-forge binaries\r\n\n\n\u003c!-- gh-linked-prs --\u003e\n### Linked PRs\n* gh-117332\n* gh-131182\n\u003c!-- /gh-linked-prs --\u003e\n","author":{"url":"https://github.com/mmohrhard","@type":"Person","name":"mmohrhard"},"datePublished":"2023-07-19T07:12:14.000Z","interactionStatistic":{"@type":"InteractionCounter","interactionType":"https://schema.org/CommentAction","userInteractionCount":9},"url":"https://github.com/106883/cpython/issues/106883"}