Stowage/cpython
2
0
Fork 0
mirror of https://github.com/python/cpython.git synced 2025-12-08 06:10:17 +00:00
Code Issues Projects Releases Packages Wiki Activity

gh-98894: Restore function entry/exit DTrace probes

Browse source 
The function__entry and function__return probes stopped working in Python 3.11
when the interpreter was restructured around the new bytecode system. This change
restores these probes by adding DTRACE_FUNCTION_ENTRY() at the start_frame label
in bytecodes.c and DTRACE_FUNCTION_RETURN() in the RETURN_VALUE and YIELD_VALUE
instructions. The helper functions are defined in ceval.c and extract the
filename, function name, and line number from the frame before firing the probe.

This builds on the approach from https://github.com/python/cpython/pull/125019
but avoids modifying the JIT template since the JIT does not currently support
DTrace. The macros are conditionally compiled with WITH_DTRACE and are no-ops
otherwise. The tests have been updated to use modern opcode names (CALL, CALL_KW,
CALL_FUNCTION_EX) and a new bpftrace backend was added for Linux CI alongside
the existing SystemTap tests. Line probe tests were removed since that probe
was never restored after 3.11.
This commit is contained in:
Pablo Galindo Salgado 2025-12-08 00:56:44 +00:00
parent ef51a7c8f3
commit b1e8453dda
12 changed files with 237 additions and 57 deletions
Download patch file Download diff file Expand all files Collapse all files

6
Lib/test/dtracedata/call_stack.py
View file

@ -5,16 +5,16 @@ def function_1():
def function_2():
function_1()
# CALL_FUNCTION_VAR
# CALL with positional args
def function_3(dummy, dummy2):
pass
# CALL_FUNCTION_KW
# CALL_KW (keyword arguments)
def function_4(**dummy):
return 1
return 2 # unreachable
# CALL_FUNCTION_VAR_KW
# CALL_FUNCTION_EX (unpacking)
def function_5(dummy, dummy2, **dummy3):
if False:
return 7

5
Lib/test/dtracedata/call_stack.stp.expected
View file

@ -1,8 +1,10 @@
function__entry:call_stack.py:start:23
function__entry:call_stack.py:function_1:1
function__entry:call_stack.py:function_3:9
function__return:call_stack.py:function_3:10
function__return:call_stack.py:function_1:2
function__entry:call_stack.py:function_2:5
function__entry:call_stack.py:function_1:1
function__return:call_stack.py:function_3:10
function__return:call_stack.py:function_1:2
function__return:call_stack.py:function_2:6
function__entry:call_stack.py:function_3:9
@ -11,4 +13,3 @@ function__entry:call_stack.py:function_4:13
function__return:call_stack.py:function_4:14
function__entry:call_stack.py:function_5:18
function__return:call_stack.py:function_5:21
function__return:call_stack.py:start:28

7
Lib/test/dtracedata/line.d
View file

@ -1,7 +0,0 @@
python$target:::line
/(copyinstr(arg1)=="test_line")/
{
printf("%d\t%s:%s:%s:%d\n", timestamp,
probename, basename(copyinstr(arg0)),
copyinstr(arg1), arg2);
}

20
Lib/test/dtracedata/line.d.expected
View file

@ -1,20 +0,0 @@
line:line.py:test_line:2
line:line.py:test_line:3
line:line.py:test_line:4
line:line.py:test_line:5
line:line.py:test_line:6
line:line.py:test_line:7
line:line.py:test_line:8
line:line.py:test_line:9
line:line.py:test_line:10
line:line.py:test_line:11
line:line.py:test_line:4
line:line.py:test_line:5
line:line.py:test_line:6
line:line.py:test_line:7
line:line.py:test_line:8
line:line.py:test_line:10
line:line.py:test_line:11
line:line.py:test_line:4
line:line.py:test_line:12
line:line.py:test_line:13

17
Lib/test/dtracedata/line.py
View file

@ -1,17 +0,0 @@
def test_line():
a = 1
print('# Preamble', a)
for i in range(2):
a = i
b = i+2
c = i+3
if c < 4:
a = c
d = a + b +c
print('#', a, b, c, d)
a = 1
print('# Epilogue', a)
if __name__ == '__main__':
test_line()

181
Lib/test/test_dtrace.py
View file

@ -33,11 +33,17 @@ def normalize_trace_output(output):
result = [
row.split("\t")
for row in output.splitlines()
if row and not row.startswith('#')
if row and not row.startswith('#') and not row.startswith('@')
]
result.sort(key=lambda row: int(row[0]))
result = [row[1] for row in result]
return "\n".join(result)
# Normalize paths to basenames (bpftrace outputs full paths)
normalized = []
for line in result:
# Replace full paths with just the filename
line = re.sub(r'/[^:]+/([^/:]+\.py)', r'\1', line)
normalized.append(line)
return "\n".join(normalized)
except (IndexError, ValueError):
raise AssertionError(
"tracer produced unparsable output:\n{}".format(output)
@ -103,6 +109,156 @@ class SystemTapBackend(TraceBackend):
COMMAND = ["stap", "-g"]
class BPFTraceBackend(TraceBackend):
EXTENSION = ".bt"
COMMAND = ["bpftrace"]
# Inline bpftrace programs for each test case
PROGRAMS = {
"call_stack": """
usdt:{python}:python:function__entry {{
printf("%lld\\tfunction__entry:%s:%s:%d\\n",
nsecs, str(arg0), str(arg1), arg2);
}}
usdt:{python}:python:function__return {{
printf("%lld\\tfunction__return:%s:%s:%d\\n",
nsecs, str(arg0), str(arg1), arg2);
}}
""",
"gc": """
usdt:{python}:python:function__entry {{
if (str(arg1) == "start") {{ @tracing = 1; }}
}}
usdt:{python}:python:function__return {{
if (str(arg1) == "start") {{ @tracing = 0; }}
}}
usdt:{python}:python:gc__start {{
if (@tracing) {{
printf("%lld\\tgc__start:%d\\n", nsecs, arg0);
}}
}}
usdt:{python}:python:gc__done {{
if (@tracing) {{
printf("%lld\\tgc__done:%lld\\n", nsecs, arg0);
}}
}}
END {{ clear(@tracing); }}
""",
}
# Which test scripts to filter by filename (None = use @tracing flag)
FILTER_BY_FILENAME = {"call_stack": "call_stack.py"}
# Expected outputs for each test case
# Note: bpftrace captures <module> entry/return and may have slight timing
# differences compared to SystemTap due to probe firing order
EXPECTED = {
"call_stack": """function__entry:call_stack.py:<module>:0
function__entry:call_stack.py:start:23
function__entry:call_stack.py:function_1:1
function__entry:call_stack.py:function_3:9
function__return:call_stack.py:function_3:10
function__return:call_stack.py:function_1:2
function__entry:call_stack.py:function_2:5
function__entry:call_stack.py:function_1:1
function__return:call_stack.py:function_3:10
function__return:call_stack.py:function_1:2
function__return:call_stack.py:function_2:6
function__entry:call_stack.py:function_3:9
function__return:call_stack.py:function_3:10
function__entry:call_stack.py:function_4:13
function__return:call_stack.py:function_4:14
function__entry:call_stack.py:function_5:18
function__return:call_stack.py:function_5:21
function__return:call_stack.py:start:28
function__return:call_stack.py:<module>:30""",
"gc": """gc__start:0
gc__done:0
gc__start:1
gc__done:0
gc__start:2
gc__done:0
gc__start:2
gc__done:1""",
}
def run_case(self, name, optimize_python=None):
if name not in self.PROGRAMS:
raise unittest.SkipTest(f"No bpftrace program for {name}")
python_file = abspath(name + ".py")
python_flags = []
if optimize_python:
python_flags.extend(["-O"] * optimize_python)
subcommand = [sys.executable] + python_flags + [python_file]
program = self.PROGRAMS[name].format(python=sys.executable)
try:
proc = subprocess.Popen(
["bpftrace", "-e", program, "-c", " ".join(subcommand)],
stdout=subprocess.PIPE,
stderr=subprocess.PIPE,
universal_newlines=True,
)
stdout, stderr = proc.communicate(timeout=60)
except subprocess.TimeoutExpired:
proc.kill()
raise AssertionError("bpftrace timed out")
except (FileNotFoundError, PermissionError) as e:
raise unittest.SkipTest(f"bpftrace not available: {e}")
if proc.returncode != 0:
raise AssertionError(
f"bpftrace failed with code {proc.returncode}:\n{stderr}"
)
# Filter output by filename if specified (bpftrace captures everything)
if name in self.FILTER_BY_FILENAME:
filter_filename = self.FILTER_BY_FILENAME[name]
filtered_lines = [
line for line in stdout.splitlines()
if filter_filename in line
]
stdout = "\n".join(filtered_lines)
actual_output = normalize_trace_output(stdout)
expected_output = self.EXPECTED[name].strip()
return (expected_output, actual_output)
def assert_usable(self):
# Check if bpftrace is available and can attach to USDT probes
program = f'usdt:{sys.executable}:python:function__entry {{ printf("probe: success\\n"); exit(); }}'
try:
proc = subprocess.Popen(
["bpftrace", "-e", program, "-c", f"{sys.executable} -c pass"],
stdout=subprocess.PIPE,
stderr=subprocess.PIPE,
universal_newlines=True,
)
stdout, stderr = proc.communicate(timeout=10)
except subprocess.TimeoutExpired:
proc.kill()
proc.communicate() # Clean up
raise unittest.SkipTest("bpftrace timed out during usability check")
except OSError as e:
raise unittest.SkipTest(f"bpftrace not available: {e}")
# Check for permission errors (bpftrace usually requires root)
if proc.returncode != 0:
raise unittest.SkipTest(
f"bpftrace(1) failed with code {proc.returncode}: {stderr}"
)
if "probe: success" not in stdout:
raise unittest.SkipTest(
f"bpftrace(1) failed: stdout={stdout!r} stderr={stderr!r}"
)
class TraceTests:
# unittest.TestCase options
maxDiff = None
@ -126,7 +282,8 @@ def test_function_entry_return(self):
def test_verify_call_opcodes(self):
"""Ensure our call stack test hits all function call opcodes"""
opcodes = set(["CALL_FUNCTION", "CALL_FUNCTION_EX", "CALL_FUNCTION_KW"])
# Modern Python uses CALL, CALL_KW, and CALL_FUNCTION_EX
opcodes = set(["CALL", "CALL_FUNCTION_EX", "CALL_KW"])
with open(abspath("call_stack.py")) as f:
code_string = f.read()
@ -151,9 +308,6 @@ def get_function_instructions(funcname):
def test_gc(self):
self.run_case("gc")
def test_line(self):
self.run_case("line")
class DTraceNormalTests(TraceTests, unittest.TestCase):
backend = DTraceBackend()
@ -174,6 +328,17 @@ class SystemTapOptimizedTests(TraceTests, unittest.TestCase):
backend = SystemTapBackend()
optimize_python = 2
class BPFTraceNormalTests(TraceTests, unittest.TestCase):
backend = BPFTraceBackend()
optimize_python = 0
class BPFTraceOptimizedTests(TraceTests, unittest.TestCase):
backend = BPFTraceBackend()
optimize_python = 2
class CheckDtraceProbes(unittest.TestCase):
@classmethod
def setUpClass(cls):
@ -234,6 +399,8 @@ def test_check_probes(self):
"Name: audit",
"Name: gc__start",
"Name: gc__done",
"Name: function__entry",
"Name: function__return",
]
for probe_name in available_probe_names:
@ -246,8 +413,6 @@ def test_missing_probes(self):
# Missing probes will be added in the future.
missing_probe_names = [
"Name: function__entry",
"Name: function__return",
"Name: line",
]

2
Misc/NEWS.d/next/Core_and_Builtins/2025-12-08-00-25-35.gh-issue-98894.hKWyfqNx.rst Normal file
View file

@ -0,0 +1,2 @@
Restore ``function__entry`` and ``function__return`` DTrace/SystemTap probes
that were broken since Python 3.11.

3
Python/bytecodes.c
View file

@ -1242,6 +1242,7 @@ dummy_func(
DEAD(retval);
SAVE_STACK();
assert(STACK_LEVEL() == 0);
DTRACE_FUNCTION_RETURN();
_Py_LeaveRecursiveCallPy(tstate);
// GH-99729: We need to unlink the frame *before* clearing it:
_PyInterpreterFrame *dying = frame;
@ -1418,6 +1419,7 @@ dummy_func(
_PyStackRef temp = retval;
DEAD(retval);
SAVE_STACK();
DTRACE_FUNCTION_RETURN();
tstate->exc_info = gen->gi_exc_state.previous_item;
gen->gi_exc_state.previous_item = NULL;
_Py_LeaveRecursiveCallPy(tstate);
@ -5564,6 +5566,7 @@ dummy_func(
if (too_deep) {
goto exit_unwind;
}
DTRACE_FUNCTION_ENTRY();
next_instr = frame->instr_ptr;
#ifdef Py_DEBUG
int lltrace = maybe_lltrace_resume_frame(frame, GLOBALS());

33
Python/ceval.c
View file

@ -1452,6 +1452,38 @@ stop_tracing_and_jit(PyThreadState *tstate, _PyInterpreterFrame *frame)
#define DONT_SLP_VECTORIZE
#endif
#ifdef WITH_DTRACE
static void
dtrace_function_entry(_PyInterpreterFrame *frame)
{
const char *filename;
const char *funcname;
int lineno;
PyCodeObject *code = _PyFrame_GetCode(frame);
filename = PyUnicode_AsUTF8(code->co_filename);
funcname = PyUnicode_AsUTF8(code->co_name);
lineno = PyUnstable_InterpreterFrame_GetLine(frame);
PyDTrace_FUNCTION_ENTRY(filename, funcname, lineno);
}
static void
dtrace_function_return(_PyInterpreterFrame *frame)
{
const char *filename;
const char *funcname;
int lineno;
PyCodeObject *code = _PyFrame_GetCode(frame);
filename = PyUnicode_AsUTF8(code->co_filename);
funcname = PyUnicode_AsUTF8(code->co_name);
lineno = PyUnstable_InterpreterFrame_GetLine(frame);
PyDTrace_FUNCTION_RETURN(filename, funcname, lineno);
}
#endif
typedef struct {
_PyInterpreterFrame frame;
_PyStackRef stack[1];
@ -1531,6 +1563,7 @@ _PyEval_EvalFrameDefault(PyThreadState *tstate, _PyInterpreterFrame *frame, int
if (_Py_EnterRecursivePy(tstate)) {
goto early_exit;
}
DTRACE_FUNCTION_ENTRY();
#ifdef Py_GIL_DISABLED
/* Load thread-local bytecode */
if (frame->tlbc_index != ((_PyThreadStateImpl *)tstate)->tlbc_index) {

13
Python/ceval_macros.h
View file

@ -305,11 +305,24 @@ GETITEM(PyObject *v, Py_ssize_t i) {
#define CONSTS() _PyFrame_GetCode(frame)->co_consts
#define NAMES() _PyFrame_GetCode(frame)->co_names
#ifdef WITH_DTRACE
static void dtrace_function_entry(_PyInterpreterFrame *);
static void dtrace_function_return(_PyInterpreterFrame *);
#define DTRACE_FUNCTION_ENTRY() \
if (PyDTrace_FUNCTION_ENTRY_ENABLED()) { \
dtrace_function_entry(frame); \
}
#define DTRACE_FUNCTION_RETURN() \
if (PyDTrace_FUNCTION_RETURN_ENABLED()) { \
dtrace_function_return(frame); \
}
#else
#define DTRACE_FUNCTION_ENTRY() ((void)0)
#define DTRACE_FUNCTION_RETURN() ((void)0)
#endif
/* This takes a uint16_t instead of a _Py_BackoffCounter,
* because it is used directly on the cache entry in generated code,
* which is always an integral type. */

2
Python/executor_cases.c.h generated
View file

@ -1925,6 +1925,7 @@
ASSERT_WITHIN_STACK_BOUNDS(__FILE__, __LINE__);
_PyFrame_SetStackPointer(frame, stack_pointer);
assert(STACK_LEVEL() == 0);
DTRACE_FUNCTION_RETURN();
_Py_LeaveRecursiveCallPy(tstate);
_PyInterpreterFrame *dying = frame;
frame = tstate->current_frame = dying->previous;
@ -2080,6 +2081,7 @@
stack_pointer += -1;
ASSERT_WITHIN_STACK_BOUNDS(__FILE__, __LINE__);
_PyFrame_SetStackPointer(frame, stack_pointer);
DTRACE_FUNCTION_RETURN();
tstate->exc_info = gen->gi_exc_state.previous_item;
gen->gi_exc_state.previous_item = NULL;
_Py_LeaveRecursiveCallPy(tstate);

5
Python/generated_cases.c.h generated
View file

@ -7093,6 +7093,7 @@
ASSERT_WITHIN_STACK_BOUNDS(__FILE__, __LINE__);
_PyFrame_SetStackPointer(frame, stack_pointer);
assert(STACK_LEVEL() == 0);
DTRACE_FUNCTION_RETURN();
_Py_LeaveRecursiveCallPy(tstate);
_PyInterpreterFrame *dying = frame;
frame = tstate->current_frame = dying->previous;
@ -7150,6 +7151,7 @@
stack_pointer += -1;
ASSERT_WITHIN_STACK_BOUNDS(__FILE__, __LINE__);
_PyFrame_SetStackPointer(frame, stack_pointer);
DTRACE_FUNCTION_RETURN();
tstate->exc_info = gen->gi_exc_state.previous_item;
gen->gi_exc_state.previous_item = NULL;
_Py_LeaveRecursiveCallPy(tstate);
@ -10056,6 +10058,7 @@
ASSERT_WITHIN_STACK_BOUNDS(__FILE__, __LINE__);
_PyFrame_SetStackPointer(frame, stack_pointer);
assert(STACK_LEVEL() == 0);
DTRACE_FUNCTION_RETURN();
_Py_LeaveRecursiveCallPy(tstate);
_PyInterpreterFrame *dying = frame;
frame = tstate->current_frame = dying->previous;
@ -11795,6 +11798,7 @@
stack_pointer += -1;
ASSERT_WITHIN_STACK_BOUNDS(__FILE__, __LINE__);
_PyFrame_SetStackPointer(frame, stack_pointer);
DTRACE_FUNCTION_RETURN();
tstate->exc_info = gen->gi_exc_state.previous_item;
gen->gi_exc_state.previous_item = NULL;
_Py_LeaveRecursiveCallPy(tstate);
@ -11970,6 +11974,7 @@ JUMP_TO_LABEL(error);
if (too_deep) {
JUMP_TO_LABEL(exit_unwind);
}
DTRACE_FUNCTION_ENTRY();
next_instr = frame->instr_ptr;
#ifdef Py_DEBUG
int lltrace = maybe_lltrace_resume_frame(frame, GLOBALS());