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-125019

[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.