python / cpython

The Python programming language
https://www.python.org
Other
63.67k stars 30.51k forks source link

sys.setprofile and equivalent C API don't track all callable C code #126056

Open itamarst opened 1 month ago

itamarst commented 1 month ago

Bug report

Bug description:

import sys
import mmap

def prof(frame, event, arg):
    print(event, arg)

sys.setprofile(prof)

x = mmap.mmap(-1, 10_000)
open("/dev/null")

When run with Python 3.13 on Linux:

c_call <built-in function open>
call None
call None
return None
return None
c_return <built-in function open>
return None

No mention of mmap.mmap(), perhaps because it's a constructor of a type object.

(This is really an issue with the underlying C API, PyTrace_C_CALL is similarly not happening.)

As someone doing profiling, this means that any code running inside C type constructors is invisible, which is problematic and means I'm going to have to change how one of my profilers works.

CPython versions tested on:

3.12, 3.13

Operating systems tested on:

Linux

gaogaotiantian commented 1 month ago

This behavior is consistent with previous versions, it's not new. So this would be a feature request, instead of a bug.

itamarst commented 1 month ago

Normal profiling catches MyKlass.__init__, so it's surprising that C types' constructors don't get profiled. So it's a bug from the perspective of what you would expect from the documented API. If bugs are limited to regressions, then yes, not really a bug.

gaogaotiantian commented 4 weeks ago

Well, not entirely. The documentation states

arg is the C function object.

which means in C API, it can be safely casted to a PyCFunctionObject* and all the related APIs and fields will be accessible. mmap.mmap does not have that. It's a type that calls the C function at tp_new to allocate and initialize the object, as most of the objects do.

So, supporting a type call, which is a breaking behavior, will actually break a lot of the profiler/debugger code out there which assumes the argument is a PyCFunctionObject*.

itamarst commented 4 weeks ago

Perhaps could be solved by adding a new PyTrace_C_OBJECT_NEW or something?

gaogaotiantian commented 4 weeks ago

It would still be a breaking change. Not only on C API level, should we add a new type of event for sys.setprofile? Because the arg is still different. How would we provide the arg? There's no Python representable data structure.

I'm not saying this can't or shouldn't be done. I'm simply stating that this is not a trivial bug fix. This is a new feature request that could potentially break plenty of the existing code, no matter how you implement it, because it breaks some assumptions that have been there for 10 years. Therefore, we'd better have a really good reason to add it.

itamarst commented 4 weeks ago

The reason I encountered this was in a memory profiler: I use PyTrace_C_CALL to record and cache the latest line number, so that C code that releases the GIL and allocates can still record the the latest Python line number for that allocation. But e.g. mmap.mmap() is invisible to the profiler, so the cached line number is out of date and the allocation gets assigned to unrelated earlier line numbers.

More broadly, having certain code paths just be invisible to Python's profiling API is likely to hit other profilers based on these APIs. E.g. a C type constructor that does a lot of compute work will get assigned to the calling function and it will be difficult for profiler users to track down where exactly the slowness is.

Given it's not in current Python I will have to fix things regardless of what you all decide about this issue. Some alternatives I'm considering: