Skip to content

gh-103533: Use pep669 APIs for cprofile #103534

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 6 commits into from
May 5, 2023
Merged

gh-103533: Use pep669 APIs for cprofile #103534

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
a59daf6
Use pep669 APIs for cprofile
gaogaotiantian Apr 14, 2023
82946fa
📜🤖 Added by blurb_it.
blurb-it[bot] Apr 14, 2023
3c88fd1
Clean up code. Report ValueError when another tool is trying to
gaogaotiantian Apr 16, 2023
2c9bed4
Make the callback table const
gaogaotiantian Apr 16, 2023
20f4663
Make global check happy
gaogaotiantian Apr 20, 2023
b7b719d
Fixed return None to NULL
gaogaotiantian May 4, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
19 changes: 14 additions & 5 deletions Lib/test/test_cprofile.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,7 +25,6 @@ def test_bad_counter_during_dealloc(self):
with support.catch_unraisable_exception() as cm:
obj = _lsprof.Profiler(lambda: int)
obj.enable()
obj = _lsprof.Profiler(1)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why has this line been removed?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because what the test was partially testing won't work anymore. The line relies on the fact that the original obj was deallocated when replace - that won't happen because it's still being referenced by the monitors.

Having that line would also cause an infinite exception loop, probably due to the new mechanism.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry not infinite, but very frequent warning. The issue is we did not disable the profiling - that's what I mentioned in the description - enabling the profiling with one object and disable it with another won't work.

obj.disable()
obj.clear()

Expand All @@ -37,10 +36,11 @@ def test_profile_enable_disable(self):
self.addCleanup(prof.disable)

prof.enable()
self.assertIs(sys.getprofile(), prof)
self.assertEqual(
sys.monitoring.get_tool(sys.monitoring.PROFILER_ID), "cProfile")

prof.disable()
self.assertIs(sys.getprofile(), None)
self.assertIs(sys.monitoring.get_tool(sys.monitoring.PROFILER_ID), None)

def test_profile_as_context_manager(self):
prof = self.profilerclass()
Expand All @@ -53,10 +53,19 @@ def test_profile_as_context_manager(self):

# profile should be set as the global profiler inside the
# with-block
self.assertIs(sys.getprofile(), prof)
self.assertEqual(
sys.monitoring.get_tool(sys.monitoring.PROFILER_ID), "cProfile")

# profile shouldn't be set once we leave the with-block.
self.assertIs(sys.getprofile(), None)
self.assertIs(sys.monitoring.get_tool(sys.monitoring.PROFILER_ID), None)

def test_second_profiler(self):
pr = self.profilerclass()
pr2 = self.profilerclass()
pr.enable()
self.assertRaises(ValueError, pr2.enable)
pr.disable()


class TestCommandLine(unittest.TestCase):
def test_sort(self):
Expand Down
1 change: 1 addition & 0 deletions Misc/NEWS.d/next/Library/2023-04-14-06-32-54.gh-issue-103533.n_AfcS.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
Update :mod:`cProfile` to use PEP 669 API
252 changes: 184 additions & 68 deletions Modules/_lsprof.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -49,6 +49,8 @@ typedef struct {
int flags;
PyObject *externalTimer;
double externalTimerUnit;
int tool_id;
PyObject* missing;
} ProfilerObject;

#define POF_ENABLED 0x001
Expand Down Expand Up @@ -399,64 +401,6 @@ ptrace_leave_call(PyObject *self, void *key)
pObj->freelistProfilerContext = pContext;
}

static int
profiler_callback(PyObject *self, PyFrameObject *frame, int what,
PyObject *arg)
{
switch (what) {

/* the 'frame' of a called function is about to start its execution */
case PyTrace_CALL:
{
PyCodeObject *code = PyFrame_GetCode(frame);
ptrace_enter_call(self, (void *)code, (PyObject *)code);
Py_DECREF(code);
break;
}

/* the 'frame' of a called function is about to finish
(either normally or with an exception) */
case PyTrace_RETURN:
{
PyCodeObject *code = PyFrame_GetCode(frame);
ptrace_leave_call(self, (void *)code);
Py_DECREF(code);
break;
}

/* case PyTrace_EXCEPTION:
If the exception results in the function exiting, a
PyTrace_RETURN event will be generated, so we don't need to
handle it. */

/* the Python function 'frame' is issuing a call to the built-in
function 'arg' */
case PyTrace_C_CALL:
if ((((ProfilerObject *)self)->flags & POF_BUILTINS)
&& PyCFunction_Check(arg)) {
ptrace_enter_call(self,
((PyCFunctionObject *)arg)->m_ml,
arg);
}
break;

/* the call to the built-in function 'arg' is returning into its
caller 'frame' */
case PyTrace_C_RETURN: /* ...normally */
case PyTrace_C_EXCEPTION: /* ...with an exception set */
if ((((ProfilerObject *)self)->flags & POF_BUILTINS)
&& PyCFunction_Check(arg)) {
ptrace_leave_call(self,
((PyCFunctionObject *)arg)->m_ml);
}
break;

default:
break;
}
return 0;
}

static int
pending_exception(ProfilerObject *pObj)
{
Expand Down Expand Up @@ -650,6 +594,99 @@ setBuiltins(ProfilerObject *pObj, int nvalue)
return 0;
}

PyObject* pystart_callback(ProfilerObject* self, PyObject *const *args, Py_ssize_t size)
{
PyObject* code = args[0];
ptrace_enter_call((PyObject*)self, (void *)code, (PyObject *)code);

Py_RETURN_NONE;
}

PyObject* pyreturn_callback(ProfilerObject* self, PyObject *const *args, Py_ssize_t size)
{
PyObject* code = args[0];
ptrace_leave_call((PyObject*)self, (void *)code);

Py_RETURN_NONE;
}

PyObject* get_cfunc_from_callable(PyObject* callable, PyObject* self_arg, PyObject* missing)
{
// return a new reference
if (PyCFunction_Check(callable)) {
Py_INCREF(callable);
return (PyObject*)((PyCFunctionObject *)callable);
}
if (Py_TYPE(callable) == &PyMethodDescr_Type) {
Copy link
Member

@markshannon markshannon May 4, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this necessary?
Doesn't the profiler extract the same data from the builtin function that it could from the method descriptor?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This piece is copied from the new setprofile I believe. The idea behind it is to make sure get_cfunc_from_callable only returns a PyCFunctionObject. If it's not, then ((PyCFunctionObject *)cfunc)->m_ml won't work.

What do you propose here? Simply return callable? We need to check that anyway because CALL event can be triggered before calling a Python function and we don't want to add profiler entry on that(it should be dealt with later). I did realize that Py_RETURN_NONE was incorrect - NULL should be returned.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All that happens to the builtin function objects is it gets passed down to normalizeUserObj() which then does some elaborate lookup to get the method descriptor back again. Both the method descriptor and builtin function contain a pointer to the same PyMethodDef struct.

So, leave the method descriptor alone here, and in normalizeUserObj() create the same string that as would be created for the builtin function.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The mo object on line 175 is the method descriptor.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There are three purposes get_cfunc_from_callable needs the serve:

  1. To get the object(callable) to print later, which could be resolved in normalizeUserObj() like you said.
  2. To get a unique key for the hash table(actually a binary tree). In this case, ((PyCFunctionObject *)cfunc)->m_ml was used, maybe the callable itself could be used as well? Not sure why m_ml was chosen at the first place, the builtin functions probably have dinstinct addresses anyway? Even for the builtin methods(like list.append), using (void*)callable directly might work?
  3. To filter out unwanted data. This is why this part is necessary. Without trying to get the C function from the method, how could we know if this is a call to a builtin function that we would like to log? It could be a simple Python call(f()), which would trigger CALL event. It could be a method call, but not to a C function(self.some_method()). We need to filter these entry out before we even reach normalizeUserObj()(that's where we are about to log the function call).

The current implementation is trying to swap out the setprofile layer without touching the internal profiling system. It's true that the profiling system could be optimized, but it's also risky and probably need extra care. If we want to land this in 3.12, maybe we should avoid changing the profiling logic for now.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree with your point about risk.

I think it is worth cleaning up the internals. We couldn't do it before, as the conversion from method descriptor to builtin function occurred before cprofile got to see it. Maybe we can get it done for 3.12, maybe not.

So let's get this change in for 3.12, and we can streamline things later.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We can clean up the internals, but we still need to address point 3. We need to filter out entries that we don't want, and that probably requires resolving the descriptors.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All the information in the fake builtin function is also in the original method descriptor, so whatever the filter was doing should still work.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do you suggest that we can get rid of Py_TYPE(callable)->tp_descr_get(callable, self_arg, (PyObject*)Py_TYPE(self_arg)) because we don't need the actual PyCFunctionObject in it? We still need to check against Py_TYPE(callable) == &PyMethodDescr_Type for the actual "builtin methods" right? To filter out Python defined methods?

/* For backwards compatibility need to
* convert to builtin method */

/* If no arg, skip */
if (self_arg == missing) {
return NULL;
}
PyObject *meth = Py_TYPE(callable)->tp_descr_get(
callable, self_arg, (PyObject*)Py_TYPE(self_arg));
if (meth == NULL) {
return NULL;
}
if (PyCFunction_Check(meth)) {
return (PyObject*)((PyCFunctionObject *)meth);
}
}
return NULL;
}

PyObject* ccall_callback(ProfilerObject* self, PyObject *const *args, Py_ssize_t size)
{
if (self->flags & POF_BUILTINS) {
PyObject* callable = args[2];
PyObject* self_arg = args[3];

PyObject* cfunc = get_cfunc_from_callable(callable, self_arg, self->missing);

if (cfunc) {
ptrace_enter_call((PyObject*)self,
((PyCFunctionObject *)cfunc)->m_ml,
cfunc);
Py_DECREF(cfunc);
}
}
Py_RETURN_NONE;
}

PyObject* creturn_callback(ProfilerObject* self, PyObject *const *args, Py_ssize_t size)
{
if (self->flags & POF_BUILTINS) {
PyObject* callable = args[2];
PyObject* self_arg = args[3];

PyObject* cfunc = get_cfunc_from_callable(callable, self_arg, self->missing);

if (cfunc) {
ptrace_leave_call((PyObject*)self,
((PyCFunctionObject *)cfunc)->m_ml);
Py_DECREF(cfunc);
}
}
Py_RETURN_NONE;
}

static const struct {
int event;
const char* callback_method;
} callback_table[] = {
{PY_MONITORING_EVENT_PY_START, "_pystart_callback"},
{PY_MONITORING_EVENT_PY_RESUME, "_pystart_callback"},
{PY_MONITORING_EVENT_PY_RETURN, "_pyreturn_callback"},
{PY_MONITORING_EVENT_PY_YIELD, "_pyreturn_callback"},
{PY_MONITORING_EVENT_PY_UNWIND, "_pyreturn_callback"},
{PY_MONITORING_EVENT_CALL, "_ccall_callback"},
{PY_MONITORING_EVENT_C_RETURN, "_creturn_callback"},
{PY_MONITORING_EVENT_C_RAISE, "_creturn_callback"},
{0, NULL}
};

PyDoc_STRVAR(enable_doc, "\
enable(subcalls=True, builtins=True)\n\
\n\
Expand All @@ -666,18 +703,46 @@ profiler_enable(ProfilerObject *self, PyObject *args, PyObject *kwds)
int subcalls = -1;
int builtins = -1;
static char *kwlist[] = {"subcalls", "builtins", 0};
int all_events = 0;

if (!PyArg_ParseTupleAndKeywords(args, kwds, "|pp:enable",
kwlist, &subcalls, &builtins))
return NULL;
if (setSubcalls(self, subcalls) < 0 || setBuiltins(self, builtins) < 0) {
return NULL;
}

PyThreadState *tstate = _PyThreadState_GET();
if (_PyEval_SetProfile(tstate, profiler_callback, (PyObject*)self) < 0) {
PyObject* monitoring = _PyImport_GetModuleAttrString("sys", "monitoring");
if (!monitoring) {
return NULL;
}

if (PyObject_CallMethod(monitoring, "use_tool_id", "is", self->tool_id, "cProfile") == NULL) {
PyErr_Format(PyExc_ValueError, "Another profiling tool is already active");
Py_DECREF(monitoring);
return NULL;
}

for (int i = 0; callback_table[i].callback_method; i++) {
PyObject* callback = PyObject_GetAttrString((PyObject*)self, callback_table[i].callback_method);
if (!callback) {
Py_DECREF(monitoring);
return NULL;
}
Py_XDECREF(PyObject_CallMethod(monitoring, "register_callback", "iiO", self->tool_id,
(1 << callback_table[i].event),
callback));
Py_DECREF(callback);
all_events |= (1 << callback_table[i].event);
}

if (!PyObject_CallMethod(monitoring, "set_events", "ii", self->tool_id, all_events)) {
Py_DECREF(monitoring);
return NULL;
}

Py_DECREF(monitoring);

self->flags |= POF_ENABLED;
Py_RETURN_NONE;
}
Expand Down Expand Up @@ -707,13 +772,44 @@ Stop collecting profiling information.\n\
static PyObject*
profiler_disable(ProfilerObject *self, PyObject* noarg)
{
PyThreadState *tstate = _PyThreadState_GET();
if (_PyEval_SetProfile(tstate, NULL, NULL) < 0) {
return NULL;
if (self->flags & POF_ENABLED) {
PyObject* result = NULL;
PyObject* monitoring = _PyImport_GetModuleAttrString("sys", "monitoring");

if (!monitoring) {
return NULL;
}

for (int i = 0; callback_table[i].callback_method; i++) {
result = PyObject_CallMethod(monitoring, "register_callback", "iiO", self->tool_id,
(1 << callback_table[i].event), Py_None);
if (!result) {
Py_DECREF(monitoring);
return NULL;
}
Py_DECREF(result);
}

result = PyObject_CallMethod(monitoring, "set_events", "ii", self->tool_id, 0);
if (!result) {
Py_DECREF(monitoring);
return NULL;
}
Py_DECREF(result);

result = PyObject_CallMethod(monitoring, "free_tool_id", "i", self->tool_id);
if (!result) {
Py_DECREF(monitoring);
return NULL;
}
Py_DECREF(result);

Py_DECREF(monitoring);

self->flags &= ~POF_ENABLED;
flush_unmatched(self);
}
self->flags &= ~POF_ENABLED;

flush_unmatched(self);
if (pending_exception(self)) {
return NULL;
}
Expand Down Expand Up @@ -778,17 +874,37 @@ profiler_init(ProfilerObject *pObj, PyObject *args, PyObject *kw)
return -1;
pObj->externalTimerUnit = timeunit;
Py_XSETREF(pObj->externalTimer, Py_XNewRef(timer));
pObj->tool_id = PY_MONITORING_PROFILER_ID;

PyObject* monitoring = _PyImport_GetModuleAttrString("sys", "monitoring");
if (!monitoring) {
return -1;
}
pObj->missing = PyObject_GetAttrString(monitoring, "MISSING");
if (!pObj->missing) {
Py_DECREF(monitoring);
return -1;
}
Py_DECREF(monitoring);
return 0;
}

static PyMethodDef profiler_methods[] = {
_LSPROF_PROFILER_GETSTATS_METHODDEF
{"enable", _PyCFunction_CAST(profiler_enable),
{"enable", _PyCFunction_CAST(profiler_enable),
METH_VARARGS | METH_KEYWORDS, enable_doc},
{"disable", (PyCFunction)profiler_disable,
{"disable", (PyCFunction)profiler_disable,
METH_NOARGS, disable_doc},
{"clear", (PyCFunction)profiler_clear,
{"clear", (PyCFunction)profiler_clear,
METH_NOARGS, clear_doc},
{"_pystart_callback", _PyCFunction_CAST(pystart_callback),
METH_FASTCALL, NULL},
{"_pyreturn_callback", _PyCFunction_CAST(pyreturn_callback),
METH_FASTCALL, NULL},
{"_ccall_callback", _PyCFunction_CAST(ccall_callback),
METH_FASTCALL, NULL},
{"_creturn_callback", _PyCFunction_CAST(creturn_callback),
METH_FASTCALL, NULL},
{NULL, NULL}
};

Expand Down
1 change: 1 addition & 0 deletions Tools/c-analyzer/cpython/ignored.tsv
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -216,6 +216,7 @@ Modules/_io/_iomodule.c - static_types -
Modules/_io/textio.c - encodefuncs -
Modules/_io/winconsoleio.c - _PyWindowsConsoleIO_Type -
Modules/_localemodule.c - langinfo_constants -
Modules/_lsprof.c - callback_table -
Modules/_pickle.c - READ_WHOLE_LINE -
Modules/_sqlite/module.c - error_codes -
Modules/_sre/sre.c pattern_repr flag_names -
Expand Down