Repository navigation
PyMonitoring_FirePyStartEvent results in incorrect duplicate calls to sys.setprofile profile functions #158711
Description
Activity
See #158748 (comment).Sorry! This one is legit. I was clicking through all the autogenerated issues and this one slipped in.
Here's a minimal reproducer for the issue, using ctypes to emulate what Cython does when a
@cython.profile(True)function is called.import ctypes import sys new_empty_code = ctypes.pythonapi.PyCode_NewEmpty new_empty_code.argtypes = [ctypes.c_char_p, ctypes.c_char_p, ctypes.c_int] new_empty_code.restype = ctypes.py_object enter_scope = ctypes.pythonapi.PyMonitoring_EnterScope enter_scope.argtypes = [ctypes.c_void_p, ctypes.POINTER(ctypes.c_uint64), ctypes.c_char_p, ctypes.c_ssize_t] enter_scope.restype = ctypes.c_int fire_py_start = ctypes.pythonapi._PyMonitoring_FirePyStartEvent fire_py_start.argtypes = [ctypes.c_void_p, ctypes.py_object, ctypes.c_int32] fire_py_start.restype = ctypes.c_int fire_py_return = ctypes.pythonapi._PyMonitoring_FirePyReturnEvent fire_py_return.argtypes = [ctypes.c_void_p, ctypes.py_object, ctypes.c_int32, ctypes.py_object] fire_py_return.restype = ctypes.c_int code = new_empty_code(b"ext.pyx", b"cython_function", 1) states = ctypes.create_string_buffer(4) version = ctypes.byref(ctypes.c_uint64(0)) start_state = states return_state = ctypes.byref(states, 2) def f(): # Do what a Cython function compiled with profile=True does when called enter_scope(states, version, b"\0\2", 2) # Events 0 and 2 are PY_START and PY_RETURN fire_py_start(start_state, code, 0) fire_py_return(return_state, code, 0, None) sys.setprofile(lambda frame, event, arg: print(event, frame.f_code.co_name)) f() sys.setprofile(None)
The output from running this is:
call f call f return f return f c_call <module>Note that this indicates that
fwas called recursively and then returned twice, when in fact it's only entered once. Note also thatcython_functionis completely missing from the output. The lastc_callis the call tosys.setprofile(None).Yeah, I agree this is a CPython bug and we should fix it. We shouldn't pass the caller's frame for an event that belongs to a different function.
I'd probably go with your first suggestion: skip the legacy callback if the code object doesn't match the current frame's code. That would still let
sys.monitoringconsumers receive the event. Creating fake frames feels like a bigger discussion.This also affects
sys.settrace, so we'd need to cover both, including returns, yields and unwinds.@pablogsal If you happen to have a chance to review, #158894 fixes this. And 3 other bugs I hit while trying to write tests for the original issue (an OOB read and 2 assertion failures) 😓
See bloomberg/memray#1037 and cython/cython#8032
The C API to programmatically trigger
sys.monitoringevents that was added in PR #116413 to solve issue #111997 and give Cython a way to trigger monitoring events for Cython frames does not work correctly with thelegacy_tracing.cimplementation ofsys.setprofileprofile functions.When Cython uses
sys.monitoringto signal that a Cython function has been entered, it creates a code object withPyCode_NewEmpty, sets a file name, function name, and line number for it, and then callsPyMonitoring_FirePyStartEvent. If there's a profile function that was installed bysys.setprofile, CPython's code inlegacy_tracing.cregisters an adapter callback that calls thesys.setprofileprofile function. That adapter callback completely ignores the code object that is passed to it, and instead passes thesys.setprofilefunction the top frame of the Python stack, as returned byPyEval_GetFrame.This interaction is completely broken: profilers installed by
sys.setprofilenever see the Cython frame, and instead see duplicates of the Python frame that called into Cython.This could be fixed by CPython checking whether the code object that the monitoring callback receives is the code object held by the top frame of the Python stack, and refusing to call the
tstate->c_profilefuncif not.Or it could be fixed by CPython detecting that condition and creating a fake frame to pass to the
c_profilefunc.Or it could be fixed by Cython falling back to not using
sys.monitoringwhenevertstate->c_profilefuncis set.I'm filing the issue against both CPython and Cython concurrently, in the hopes that if it's agreed this is a CPython bug the bugfix might get backported to 3.13 (which I think is, technically, getting one extra week of bug fix support, since 3.15.0 was delayed!)
Linked PRs