Some DTrace probes are broken in 3.11

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

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

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

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.

@brandtbucher

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

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

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.

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.

pythongh-98894: Update DTrace Docs in instrumentation.rst

pythongh-98894: Restore function entry/exit DTrace probes

fixup! pythongh-98894: Restore function entry/exit DTrace probes

[3.15] gh-98894: Skip test_dtrace when building without dtrace (GH-15…

[3.13] gh-98894: Skip test_dtrace when building without dtrace (GH-15…

pythongh-98894: Check readelf failures in test_dtrace

gh-98894: Check readelf failures in test_dtrace (#152345)

[3.15] gh-98894: Check readelf failures in test_dtrace (GH-152345) (#…

gh-98894: Check tracer exit status in test_dtrace (#152893)

pythongh-98894: Quote test_dtrace tracer subcommands

[3.15] gh-98894: Check tracer exit status in test_dtrace (GH-152893) (#…

gh-98894: Quote test_dtrace tracer subcommands (#152901)

[3.15] gh-98894: Quote test_dtrace tracer subcommands (GH-152901) (#1…

pythongh-98894: Fix dtrace tests in shared builds

gh-98894: Fix dtrace tests in shared builds (#153372)

pythongh-98894: Fix dtrace tests in shared builds (python#153372)

[3.15] gh-98894: Fix dtrace tests in shared builds (GH-153372) (#155803)

Navigation Menu

Repository navigation

Some DTrace probes are broken in 3.11 #98894

Crash report

Error messages

Expected result

Your environment

Linked PRs

14 remaining items

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Some DTrace probes are broken in 3.11 #98894

Description

Crash report

Error messages

Expected result

Your environment

Linked PRs

Activity

brandtbucher commented on Nov 18, 2022

citrus-it commented on Nov 19, 2022

lukaszachy commented on Mar 9, 2023

encukou commented on Apr 19, 2023

brandtbucher commented on Apr 19, 2023

Bill-Sommerfeld commented on Feb 9, 2024

Bill-Sommerfeld commented on Feb 9, 2024

14 remaining items

Metadata

Metadata

Assignees

Labels

Projects

Milestone

Relationships

Development

Issue actions