Repository navigation
Add a new interface for external profilers and debuggers to get the call stack efficiently #115946
Description
Activity
This certainly requires the attention of @markshannon and @Fidget-Spinner.
The continuous cost is just one pointer write per function call, which is negligible.
Looking at the code in the PR I see one pointer write, one counter increment, and several reads. We probably want a benchmark run.
Looking at the code in the PR I see one pointer write, one counter increment, and several reads. We probably want a benchmark run.
Absolutely! Also the PR doesn't work in the current state because I am missing a lot of the work in the new interpreter structure so I may need some help here to know where to put the tracking code. EDIT: I have also updated the description to reflect that it's not just one write
@gvanrossum Do you think it's worth discussing this in one Faster CPython sync?
Perhaps. Especially if you're not 100% satisfied with my answers. (Wait a day for @markshannon to pitch in as well.)
I don't know if you still have the meeting in your calendar -- we haven't seen you in a while, but of course you're always welcome! We now meet every other week. The next one is Wed March 13. The Teams meeting is now owned by Michael Droettboom.
Perhaps. Especially if you're not 100% satisfied with my answers. (Wait a day for @markshannon to pitch in as well.)
I am satisfied (and thanks a lot for taking the time to read my comments and to answer, I really appreciate it). I think is more than it seems that there are some moving pieces and some compromises to be made and I think a realtime discussion can make this easier.
I don't know if you still have the meeting in your calendar -- we haven't seen you in a while, but of course you're always welcome! We now meet every other week. The next one is Wed March 13. The Teams meeting is now owned by Michael Droettboom.
I do have it still! Should I reach out to Michael (after leaving time for @markshannon to answer first) to schedule the topic?
Agreed.
I do have it still! Should I reach out to Michael (after leaving time for @markshannon to answer first) to schedule the topic?
Wouldn't hurt to get this on the agenda early.
While this might make life easier for profilers and out-of-process debuggers (what's wrong with in-process debuggers?), it will make all Python programs slower.
To me, this cost considerably outweighs the benefits.While this might make life easier for profilers and out-of-process debuggers (what's wrong with in-process debuggers?), it will make all Python programs slower. To me, this cost considerably outweighs the benefits.
Think of this not just as a way to make the profiler life easier, but also a way to not make it break once we start inlining things or to make the JIT not push frames. If we don't do this, what do you propose we should do to not break these tools once the JIT is there or we start inlining stuff and frames start to be missing?
(what's wrong with in-process debuggers?)
That you cannot use them if Python is frozen or deadlocked and you need them if you want to attach to an already-running tool.
I'd like to remind all participants in this conversation to remain open to the issues others are trying to deal with. We will eventually need some kind of compromise. Please try working towards one.
Reacted by Pablo Galindo SalgadoReacted by Pablo Galindo Salgado@markshannon What would be an acceptable approach/compromise for you to ensure that we can still offer reliable information for these tools in a way that doesn't impact too much the runtime?
@pablogsal I wonder if you could write a bit more about how such tools currently use the frame stack (and how this has evolved through the latest Python versions, e.g. how they coped with 3.10/3.11 call inlining, whether 3.12 posed any new issues, how different 3.13 is currently? And I'd like to understand how having just a stack of code objects (as this PR seems to be doing) will help. I think I recall you mentioned that reading the frame stack is inefficient -- a bit more detail would be helpful.
IIUC the current JIT still maintains the frame stack, just as the Tier 2 interpreter does -- this is done using the
_PUSH_FRAMEand_POP_FRAMEuops, and a few related ones that you can find by searching bytecodes.c for_PUSH_FRAME.The current (modest) plans for call inlining in 3.13 (if we do it at all) only remove the innermost frame, and only if that frame doesn't make any calls into C code that could recursively enter the interpreter. (This is supported by escape analysis which can be overridden by the "pure" qualifier in bytecodes.c.) When you catch it executing uops (either in the JIT or in the Tier 2 interpreter) the frame is that of the caller and the inlined code just uses some extra stack space. (I realize there's an open issue regarding how we'd calculate the line number when the VM is in this state.)
13 remaining items
Hummm, that's interesting but it's still not conclusive because we are not seeing full linear independent stacks that we can check that are not missing anything. We should inspect the actual full per-event stacks. We can do that by running "perf script" over the file and check that we are not missing frames.
I will run a bunch of tests if someone can point me out to some example code that surely gets jitted that has a bunch of stack frames
Reacted by Aniket Panse and Michael DroettboomAdditionally there is another check: perf uses libubwind (or libdw) as unwinder. What happens if you try to unwind using libubwind under a kitted frame?
@brandtbucher and I did the test back in the day and it failed.
Also what happens if gdb tries to unwind? That's an easier check to do 🤔
I will run a bunch of tests if someone can point me out to some example code that surely gets jitted that has a bunch of stack frames
import operator def f(n): if n <= 0: return for _ in range(16): operator.call(f, n - 1) f(6)
You should usually see
njit frames with C code between them once it's warmed up a bit. Feel free to crank the numbers up higher if you need a deeper stack or a longer-running process.Reacted by Pablo Galindo Salgado@brandtbucher and I did the test back in the day and it failed.
One important thing has changed since then: the JIT no longer omits frame pointers when compiling templates. So this may just be fixed now (not sure).
Ok, I tested with the latest JIT and I can confirm neither gdb nor libunwind can unwind through the JIT. I used this extension:
#include <Python.h> #include <libunwind.h> #include <stdio.h> static PyObject* print_full_stack(PyObject* self, PyObject* args) { unw_cursor_t cursor; unw_context_t context; unw_getcontext(&context); unw_init_local(&cursor, &context); while (unw_step(&cursor) > 0) { unw_word_t offset, pc; char symbol[256]; unw_get_reg(&cursor, UNW_REG_IP, &pc); unw_get_proc_name(&cursor, symbol, sizeof(symbol), &offset); printf("0x%lx: (%s+0x%lx)\n", (unsigned long)pc, symbol, (unsigned long)offset); } return Py_None; } static PyMethodDef methods[] = { {"print_full_stack", print_full_stack, METH_NOARGS, "Print the full stack trace"}, {NULL, NULL, 0, NULL} }; static struct PyModuleDef module = { PyModuleDef_HEAD_INIT, "full_stack_trace", NULL, -1, methods }; PyMODINIT_FUNC PyInit_full_stack_trace(void) { return PyModule_Create(&module); }with @brandtbucher example:
import operator import full_stack_trace def f(n): if n <= 0: full_stack_trace.print_full_stack() return for _ in range(16): operator.call(f, n - 1) f(6)Attaching with gdb and unwinding shows:
Breakpoint 1, 0x0000fffff76a0938 in print_full_stack () from /src/full_stack_trace.so (gdb) bt #0 0x0000fffff76a0938 in print_full_stack () from /src/full_stack_trace.so #1 0x0000aaaaaabf8ccc in cfunction_vectorcall_NOARGS (func=0xfffff7b33e20, args=<optimized out>, nargsf=<optimized out>, kwnames=<optimized out>) at Objects/methodobject.c:484 #2 0x0000aaaaaab97920 in _PyObject_VectorcallTstate (kwnames=<optimized out>, nargsf=<optimized out>, args=<optimized out>, callable=0xfffff7b33e20, tstate=0xaaaaab059a90 <_PyRuntime+231872>) at ./Include/internal/pycore_call.h:168 #3 PyObject_Vectorcall (callable=0xfffff7b33e20, args=<optimized out>, nargsf=<optimized out>, kwnames=<optimized out>) at Objects/call.c:327 #4 0x0000aaaaaab32b78 in _PyEval_EvalFrameDefault (tstate=0xaaaaab059a90 <_PyRuntime+231872>, frame=0xfffff7fbe3b0, throwflag=-144045772) at Python/generated_cases.c.h:817 #5 0x0000aaaaaab97920 in _PyObject_VectorcallTstate (kwnames=<optimized out>, nargsf=<optimized out>, args=<optimized out>, callable=0xfffff7ac6e80, tstate=0xaaaaab059a90 <_PyRuntime+231872>) at ./Include/internal/pycore_call.h:168 #6 PyObject_Vectorcall (callable=0xfffff7ac6e80, args=<optimized out>, nargsf=<optimized out>, kwnames=<optimized out>) at Objects/call.c:327 #7 0x0000fffff76b9578 in ?? () #8 0x0000fffff7b517b0 in ?? () Backtrace stopped: previous frame inner to this frame (corrupt stack?)and libunwind shows:
0xaaaaaabf8ccc: (cfunction_vectorcall_NOARGS+0x6c) 0xffffffffd040: (+0x6c) 0xffffffffd040: (+0x6c)This is with frame pointers:
./python.exe -m sysconfig | grep frame CFLAGS = "-fno-strict-overflow -Wsign-compare -DNDEBUG -g -O3 -Wall -fno-omit-frame-pointer" LIBEXPAT_CFLAGS = "-I./Modules/expat -fno-strict-overflow -Wsign-compare -DNDEBUG -g -O3 -Wall -fno-omit-frame-pointer -D_Py_JIT -std=c11 -Wextra -Wno-unused-parameter -Wno-missing-field-initializers -Wstrict-prototypes -Werror=implicit-function-declaration -fvisibility=hidden -I./Include/internal -I./Include/internal/mimalloc -I. -I./Include -fPIC" LIBHACL_CFLAGS = "-I./Modules/_hacl/include -D_BSD_SOURCE -D_DEFAULT_SOURCE -fno-strict-overflow -Wsign-compare -DNDEBUG -g -O3 -Wall -fno-omit-frame-pointer -D_Py_JIT -std=c11 -Wextra -Wno-unused-parameter -Wno-missing-field-initializers -Wstrict-prototypes -Werror=implicit-function-declaration -fvisibility=hidden -I./Include/internal -I./Include/internal/mimalloc -I. -I./Include -fPIC" LIBMPDEC_CFLAGS = "-I./Modules/_decimal/libmpdec -DCONFIG_64=1 -DANSI=1 -DHAVE_UINT128_T=1 -fno-strict-overflow -Wsign-compare -DNDEBUG -g -O3 -Wall -fno-omit-frame-pointer -D_Py_JIT -std=c11 -Wextra -Wno-unused-parameter -Wno-missing-field-initializers -Wstrict-prototypes -Werror=implicit-function-declaration -fvisibility=hidden -I./Include/internal -I./Include/internal/mimalloc -I. -I./Include -fPIC" PYTHONFRAMEWORKDIR = "no-framework" PY_BUILTIN_MODULE_CFLAGS = "-fno-strict-overflow -Wsign-compare -DNDEBUG -g -O3 -Wall -fno-omit-frame-pointer -D_Py_JIT -std=c11 -Wextra -Wno-unused-parameter -Wno-missing-field-initializers -Wstrict-prototypes -Werror=implicit-function-declaration -fvisibility=hidden -I./Include/internal -I./Include/internal/mimalloc -I. -I./Include -DPy_BUILD_CORE_BUILTIN" PY_CFLAGS = "-fno-strict-overflow -Wsign-compare -DNDEBUG -g -O3 -Wall -fno-omit-frame-pointer" PY_CORE_CFLAGS = "-fno-strict-overflow -Wsign-compare -DNDEBUG -g -O3 -Wall -fno-omit-frame-pointer -D_Py_JIT -std=c11 -Wextra -Wno-unused-parameter -Wno-missing-field-initializers -Wstrict-prototypes -Werror=implicit-function-declaration -fvisibility=hidden -I./Include/internal -I./Include/internal/mimalloc -I. -I./Include -DPy_BUILD_CORE" PY_STDMODULE_CFLAGS = "-fno-strict-overflow -Wsign-compare -DNDEBUG -g -O3 -Wall -fno-omit-frame-pointer -D_Py_JIT -std=c11 -Wextra -Wno-unused-parameter -Wno-missing-field-initializers -Wstrict-prototypes -Werror=implicit-function-declaration -fvisibility=hidden -I./Include/internal -I./Include/internal/mimalloc -I. -I./Include"I will check with perf later in the day
I checked and I can confirm perf cannot unwind throughout the JIT (with or without frame pointers). For this I used @brandtbucher script:
import operator def f(n): if n <= 0: return for _ in range(16): operator.call(f, n - 1) f(10)I started it with
./python script.py, let it run for a while so the JIT is warmed up and then in another terminal attached with perf:sudo -E perf record -F9999 -g -p PIDI let it run for a while and then run
perf scriptover the result file and got this:python 2794949 13914841.174912: 100010 cpu-clock:pppH: 564f70647239 _PyEval_EvalFrameDefault+0x3e9 (/home/ubuntu/cpython/python) 564f706b368c PyObject_Vectorcall+0x3c (/home/ubuntu/cpython/python) 7f8abbece445 [unknown] (/tmp/perf-2794949.map) 564f70b17440 [unknown] ([unknown]) 564f70aeb940 [unknown] ([unknown]) python 2794949 13914841.175012: 100010 cpu-clock:pppH: 564f7080bb43 _PyEval_Vector+0xa3 (/home/ubuntu/cpython/python) 564f706b368c PyObject_Vectorcall+0x3c (/home/ubuntu/cpython/python) 7f8abbece445 [unknown] (/tmp/perf-2794949.map) 564f70b17440 [unknown] ([unknown]) 564f70aeb940 [unknown] ([unknown]) python 2794949 13914841.175112: 100010 cpu-clock:pppH: 564f7064e535 _PyEval_EvalFrameDefault+0x76e5 (/home/ubuntu/cpython/python) 564f706b368c PyObject_Vectorcall+0x3c (/home/ubuntu/cpython/python) 7f8abbece445 [unknown] (/tmp/perf-2794949.map) 564f70b17440 [unknown] ([unknown]) 564f70aeb940 [unknown] ([unknown]) python 2794949 13914841.175212: 100010 cpu-clock:pppH: 564f70809aa8 _PyEvalFramePushAndInit+0x8 (/home/ubuntu/cpython/python) 564f7080bb36 _PyEval_Vector+0x96 (/home/ubuntu/cpython/python) 564f706b368c PyObject_Vectorcall+0x3c (/home/ubuntu/cpython/python) 7f8abbece445 [unknown] (/tmp/perf-2794949.map) 564f70b17440 [unknown] ([unknown]) 564f70aeb940 [unknown] ([unknown]) python 2794949 13914841.175312: 100010 cpu-clock:pppH: 564f70647234 _PyEval_EvalFrameDefault+0x3e4 (/home/ubuntu/cpython/python) 564f706b368c PyObject_Vectorcall+0x3c (/home/ubuntu/cpython/python) 7f8abbece445 [unknown] (/tmp/perf-2794949.map) 564f70b17440 [unknown] ([unknown]) 564f70aeb940 [unknown] ([unknown]) python 2794949 13914841.175412: 100010 cpu-clock:pppH: 564f70808866 initialize_locals+0x6 (/home/ubuntu/cpython/python) 564f70809b5e _PyEvalFramePushAndInit+0xbe (/home/ubuntu/cpython/python) 564f7080bb36 _PyEval_Vector+0x96 (/home/ubuntu/cpython/python) 564f706b368c PyObject_Vectorcall+0x3c (/home/ubuntu/cpython/python) 7f8abbece445 [unknown] (/tmp/perf-2794949.map) 564f70b17440 [unknown] ([unknown]) 564f70aeb940 [unknown] ([unknown])So as you can see every time perf his a Jitted frame, it fails to unwind. @mdboom I think what you are getting in your script it's these partial frames reordered, not the full stack. You can confirm running
perf scriptand then finding one stack that has fitted frames and check if the topmost frame ismain()or__libc_mainNote that if we confirm this it means that any current attribution of Perf to jitted frames it's inaccurate
@pablogsal: Can you be more specific about how you are running
perf script?Note that if we confirm this it means that any current attribution of Perf to jitted frames it's inaccurate
If I'm understanding correctly, I see how this means that where the JIT'ted code in the stack is inaccurate, but I don't see how it follows that time attributed to JIT'ted code is inaccurate (which I realize is the easier subset of this whole problem). The numbers certainly add up and make sense.
@pablogsal: Can you be more specific about how you are running
perf script?Assuming your result file it's called "perf.data" (the default) you can just run
perf scriptotherwise you need to specify the name of the file withperf script -iIf I'm understanding correctly, I see how this means that where the JIT'ted code in the stack is inaccurate, but I don't see how it follows that time attributed to JIT'ted code is inaccurate (which I realize is the easier subset of this whole problem). The numbers certainly add up and make sense.
This is not a problem if you only account for leaf frames and we believe Perf is correctly identifying jitted frames in all cases in these conditions. If you need to account for callers, because it cannot unwind the stack it cannot discover that above a given frame there are multiple jitted frames (like in @brandtbucher example) and therefore if you measure anything other than self-time (as opposed to self-time + children time, as in flamegraphs) it will be inaccurate.
therefore if you measure anything other than self-time (as opposed to self-time + children time, as in flamegraphs) it will be inaccurate.
Got it, that makes sense.
I can confirm the output of
perf scriptdoesn't trace all the way to the root. This is true even if you provideperf-$PID.mapentries (it was a long shot, but I thought maybe providing the code size metadata might help).Disclaimer: I work on continuous profiler for Python at Datadog.
Our profiler, and I believe py-spy too, follow the pattern of what's described in @pablogsal's comment here. And our profiler work as an outside-in profiler, meaning it runs in a separate native thread in the same process as the profiled Python application. It doesn't rely on GIL when copying CPython internal states.
From CPython 3.11+, we've been using
datastack_chunk, and it helped reducing the number ofprocess_vm_readvcalls we need to make to copy_PyInterpreterFrameobjects. However, since 3.13, more specifically since gh-105727, we need to also iterate_PyInterpreterFramechecking whetherf_executableis ofPyCode_Type, basically doing as noted by @markshannon here. This required us also to issue anotherprocess_vm_readvcall asf_executableis a pointer.This also made me wonder whether there could be something equivalent of
datastack_chunkfor code objects, too. And was speculating whether faster-cpython/ideas#675 could help us achieve this or not. We already havedatastack_chunkbasically for data part, and would need control stack holding on to code objects. Correct me if I'm misunderstanding anything here, please.More broadly, I'm interested in CPython having a C API that could be used by profiler and debugger tools out there to get stack trace as efficient as possible. I believe there's a Python API for doing so, but the fact that there are quiet a few tools following the same pattern using
process_vm_readvsuggests that something is missing in C side.
Currently, external profilers and debuggers need to issue one system call per frame object when they are retrieving the call stack from a remote process as these form a linked list. Furthermore, for every frame object they need at least two or three more system calls to retrieve the code object and the code object name and file. This has several disadvantages:
For these reasons, I propose to add a new interface consisting in a contiguous array of pointers that always contains all the code objects necessary to retrieve the call stack. This has the following advantages:
process_vm_readv).Linked PRs