From b1e8453dda376bd365a0a2a65465fd38bb8e1768 Mon Sep 17 00:00:00 2001 From: Pablo Galindo Salgado Date: Mon, 8 Dec 2025 00:56:44 +0000 Subject: [PATCH] gh-98894: Restore function entry/exit DTrace probes 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. --- Lib/test/dtracedata/call_stack.py | 6 +- Lib/test/dtracedata/call_stack.stp.expected | 5 +- Lib/test/dtracedata/line.d | 7 - Lib/test/dtracedata/line.d.expected | 20 -- Lib/test/dtracedata/line.py | 17 -- Lib/test/test_dtrace.py | 181 +++++++++++++++++- ...12-08-00-25-35.gh-issue-98894.hKWyfqNx.rst | 2 + Python/bytecodes.c | 3 + Python/ceval.c | 33 ++++ Python/ceval_macros.h | 13 ++ Python/executor_cases.c.h | 2 + Python/generated_cases.c.h | 5 + 12 files changed, 237 insertions(+), 57 deletions(-) delete mode 100644 Lib/test/dtracedata/line.d delete mode 100644 Lib/test/dtracedata/line.d.expected delete mode 100644 Lib/test/dtracedata/line.py create mode 100644 Misc/NEWS.d/next/Core_and_Builtins/2025-12-08-00-25-35.gh-issue-98894.hKWyfqNx.rst diff --git a/Lib/test/dtracedata/call_stack.py b/Lib/test/dtracedata/call_stack.py index ee9f3ae8d6c9f4..11c0369d4baa04 100644 --- a/Lib/test/dtracedata/call_stack.py +++ b/Lib/test/dtracedata/call_stack.py @@ -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 diff --git a/Lib/test/dtracedata/call_stack.stp.expected b/Lib/test/dtracedata/call_stack.stp.expected index 32cf396f820629..6f8c19847ec517 100644 --- a/Lib/test/dtracedata/call_stack.stp.expected +++ b/Lib/test/dtracedata/call_stack.stp.expected @@ -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 diff --git a/Lib/test/dtracedata/line.d b/Lib/test/dtracedata/line.d deleted file mode 100644 index 03f22db6fcc1a0..00000000000000 --- a/Lib/test/dtracedata/line.d +++ /dev/null @@ -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); -} diff --git a/Lib/test/dtracedata/line.d.expected b/Lib/test/dtracedata/line.d.expected deleted file mode 100644 index 9b16ce76ee60a4..00000000000000 --- a/Lib/test/dtracedata/line.d.expected +++ /dev/null @@ -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 diff --git a/Lib/test/dtracedata/line.py b/Lib/test/dtracedata/line.py deleted file mode 100644 index 0930ff391f7a05..00000000000000 --- a/Lib/test/dtracedata/line.py +++ /dev/null @@ -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() diff --git a/Lib/test/test_dtrace.py b/Lib/test/test_dtrace.py index e1adf8e9748506..861468a710848c 100644 --- a/Lib/test/test_dtrace.py +++ b/Lib/test/test_dtrace.py @@ -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 entry/return and may have slight timing + # differences compared to SystemTap due to probe firing order + EXPECTED = { + "call_stack": """function__entry:call_stack.py::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::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", ] diff --git a/Misc/NEWS.d/next/Core_and_Builtins/2025-12-08-00-25-35.gh-issue-98894.hKWyfqNx.rst b/Misc/NEWS.d/next/Core_and_Builtins/2025-12-08-00-25-35.gh-issue-98894.hKWyfqNx.rst new file mode 100644 index 00000000000000..09ccf198a90583 --- /dev/null +++ b/Misc/NEWS.d/next/Core_and_Builtins/2025-12-08-00-25-35.gh-issue-98894.hKWyfqNx.rst @@ -0,0 +1,2 @@ +Restore ``function__entry`` and ``function__return`` DTrace/SystemTap probes +that were broken since Python 3.11. diff --git a/Python/bytecodes.c b/Python/bytecodes.c index 4ba255d28bdcf6..296bcf1b5274a9 100644 --- a/Python/bytecodes.c +++ b/Python/bytecodes.c @@ -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()); diff --git a/Python/ceval.c b/Python/ceval.c index a1d54bd058bc49..38eb91ea5cbff6 100644 --- a/Python/ceval.c +++ b/Python/ceval.c @@ -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) { diff --git a/Python/ceval_macros.h b/Python/ceval_macros.h index edf8fc9a57d74e..41646970fc6420 100644 --- a/Python/ceval_macros.h +++ b/Python/ceval_macros.h @@ -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. */ diff --git a/Python/executor_cases.c.h b/Python/executor_cases.c.h index 7273a87681b4dd..908dd1afd1e9bf 100644 --- a/Python/executor_cases.c.h +++ b/Python/executor_cases.c.h @@ -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); diff --git a/Python/generated_cases.c.h b/Python/generated_cases.c.h index 68d73cccec4d6b..c6cf3dfa17ffe6 100644 --- a/Python/generated_cases.c.h +++ b/Python/generated_cases.c.h @@ -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());