Some DTrace probes are broken in 3.11

[Elias-elastisys]

Crash report

I've been using eBPF with the static markers in Python 3.10 and wanted to try out 3.11 now that it is released.

But it seems that the function__entry and line markers are broken in 3.11.

The function__entry probe simply does not fire into the eBPF program.
The line probe crashes the interpreter.

I'm using BCC to load the eBPF program like this:

#!/usr/bin/python3

import argparse
from bcc import BPF, USDT

parser = argparse.ArgumentParser()
parser.add_argument("pid", type=int)
args = parser.parse_args()

program = """
int trace_entry(struct pt_regs *ctx){
 bpf_trace_printk("Entry:");

 return 0;
}

int trace_return(struct pt_regs *ctx){
 bpf_trace_printk("Return:");

 return 0;
}

int trace_line(struct pt_regs *ctx){
 bpf_trace_printk("Line:");

 return 0;
}
"""

usdt = USDT(pid=args.pid)
usdt.enable_probe_or_bail("python:function__entry", 'trace_entry')
usdt.enable_probe_or_bail("python:function__return", 'trace_return')
usdt.enable_probe_or_bail("python:line", 'trace_line')

bpf = BPF(text=program, usdt_contexts=[usdt] if usdt else [], debug=0)

try:
 bpf.trace_print()
except KeyboardInterrupt:
 exit()

If I don't enable the line probe this is the output:

❯ sudo ./ebpf-test.py 80715
b' python-80715 [001] d...1 6539.145626: bpf_trace_printk: Return:'

The entry message is never printed.

Error messages

With the line probe enabled, this is the crash error:

❯ ./python
Python 3.11.0+ (heads/3.11:57dd11038f, Oct 31 2022, 10:30:28) [GCC 11.3.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> print("Hello world!")
python: Python/ceval.c:5620: _PyEval_EvalFrameDefault: Assertion `cframe.use_tracing' failed.
[1] 80398 IOT instruction (core dumped) ./python

Expected result

Running the same test in 3.10.6 I get this result, as expected:

❯ python3 
Python 3.10.6 (main, Aug 10 2022, 11:40:04) [GCC 11.3.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> print("Hello world!")
Hello world!

❯ sudo ./ebpf-test.py 81962
b' python3-81962 [003] d...1 6907.857690: bpf_trace_printk: Entry:'
b' python3-81962 [003] d...1 6907.857710: bpf_trace_printk: Line:'
b' python3-81962 [003] d...1 6907.857765: bpf_trace_printk: Return:'

Your environment

I used the head of the 3.11 branch with ./configure --with-dtrace --with-pydebug
On Ubuntu 22.04.

Linked PRs

• GH-98894: Fix function__return and function__entry dTrace probe missing after GH-103083 #125019
• gh-98894: Update DTrace Docs in instrumentation.rst #139334
• gh-98894: Restore function entry/exit DTrace probes #142397

[brandtbucher]

Thanks, I'll take a look at this soon.

[citrus-it]

I am seeing the same behaviour on illumos with the function-entry dtrace probe - it's firing but not for much, and not for functions defined in the test program. The dtrace tests fail.

build:cpython:heads/v3.11.0% uname -a
SunOS build 5.11 omnios-r151044-d3b715b9d1 i86pc i386 i86pc

build:cpython:heads/v3.11.0% LD_LIBRARY_PATH=. \
> dtrace -s Lib/test/dtracedata/call_stack.d \
> -c './python Lib/test/dtracedata/call_stack.py'
dtrace: script 'Lib/test/dtracedata/call_stack.d' matched 10 probes
dtrace: pid 11421 has exited

build:cpython:heads/v3.11.0% LD_LIBRARY_PATH=. \
 dtrace -n 'python$target:::function-entry{trace(copyinstr(arg1))}' \
 -c './python Lib/test/dtracedata/call_stack.py'
dtrace: description 'python$target:::function-entry' matched 2 probes
dtrace: pid 13756 has exited
CPU ID FUNCTION:NAME
 12 99130 dtrace_function_entry:function-entry <genexpr>
 12 99130 dtrace_function_entry:function-entry <lambda>
 12 99130 dtrace_function_entry:function-entry _coro
 12 99130 dtrace_function_entry:function-entry _ag

build:cpython:heads/v3.11.0% LD_LIBRARY_PATH=. \
 dtrace -ln 'python$target:::' \
 -c './python Lib/test/dtracedata/call_stack.py'
 ID PROVIDER MODULE FUNCTION NAME
99126 python15257 libpython3.11.so.1.0 sys_audit_tstate audit
99127 python15257 libpython3.11.so.1.0 sys_audit_tstate.cold audit
99128 python15257 libpython3.11.so.1.0 sys_audit audit
99129 python15257 libpython3.11.so.1.0 _PyEval_EvalFrameDefault function-entry
99130 python15257 libpython3.11.so.1.0 dtrace_function_entry function-entry
99131 python15257 libpython3.11.so.1.0 _PyEval_EvalFrameDefault function-return
99132 python15257 libpython3.11.so.1.0 dtrace_function_return function-return
99133 python15257 libpython3.11.so.1.0 _PyEval_EvalFrameDefault.cold function-return
99134 python15257 libpython3.11.so.1.0 gc_collect_main.cold gc-done
99135 python15257 libpython3.11.so.1.0 gc_collect_main gc-done
99136 python15257 libpython3.11.so.1.0 gc_collect_main.cold gc-start
99137 python15257 libpython3.11.so.1.0 gc_collect_main gc-start
99138 python15257 libpython3.11.so.1.0 PyImport_ImportModuleLevelObject.cold import-find-load-done
99139 python15257 libpython3.11.so.1.0 PyImport_ImportModuleLevelObject.cold import-find-load-start
99140 python15257 libpython3.11.so.1.0 _PyEval_EvalFrameDefault line
99141 python15257 libpython3.11.so.1.0 _PyEval_EvalFrameDefault.cold line

Edit: the line probe seems fine:

build:cpython:heads/v3.11.0% LD_LIBRARY_PATH=. \
 dtrace -n 'python$target:::line{printf("%s:%d", copyinstr(arg1), arg2)}' \
 -c './python Lib/test/dtracedata/call_stack.py' | sed -n '/start/,$p'
dtrace: description 'python$target:::line' matched 2 probes
dtrace: pid 20479 has exited
 27 99141 _PyEval_EvalFrameDefault.cold:line start:24
 27 99141 _PyEval_EvalFrameDefault.cold:line function_1:2
 27 99141 _PyEval_EvalFrameDefault.cold:line function_3:10
 27 99141 _PyEval_EvalFrameDefault.cold:line start:25
 27 99141 _PyEval_EvalFrameDefault.cold:line function_2:6
 27 99141 _PyEval_EvalFrameDefault.cold:line function_1:2
 27 99141 _PyEval_EvalFrameDefault.cold:line function_3:10
 27 99141 _PyEval_EvalFrameDefault.cold:line start:26
 27 99141 _PyEval_EvalFrameDefault.cold:line function_3:10
 27 99141 _PyEval_EvalFrameDefault.cold:line start:27
 27 99141 _PyEval_EvalFrameDefault.cold:line function_4:14
 27 99141 _PyEval_EvalFrameDefault.cold:line start:28
 27 99141 _PyEval_EvalFrameDefault.cold:line function_5:19
 27 99141 _PyEval_EvalFrameDefault.cold:line function_5:21

[lukaszachy]

Hi, could this issue be also the reason why following systemtap probe is not printing anything for python3.11?

Probe:

#!/usr/bin/stap -v
probe python.function.entry
{
 if ( filename =~ "random" )
 printf("%s => %s in %s:%d\n", thread_indent(1), funcname, filename, lineno);
}

Simple python script

import random, time
print(random.random())
time.sleep(3)

To reproduce run stap probe.stp -v -c "python3.11 script.py". I've tried python3.11 available in Fedora 37 or centos-stream-9.

[encukou]

@brandtbucher, do you still intend to look at this?

[brandtbucher]

Probably not… this stuff seems to have changed quite a bit recently, and I was never too familiar with it in the first place.

[Bill-Sommerfeld]

I took a look at this yesterday in 3.12 as part of my current effort to package 3.12 for OpenIndiana (illumos) and I got the function entry/exit probes restored and working well enough to pass the test_dtrace.py test.

I'll share when I get a chance - I'm doing this with original dtrace on illumos (the open-source continuation of opensolaris) but it would likely also work for those who want to use these probes via systemtap.

[Bill-Sommerfeld]

As I mentioned in #104280 I have the function-entry and function-return probes restored in https://github.com/Bill-Sommerfeld/cpython/tree/dtrace-3.12

I'd appreciate it if others could give it a look.