Bug 29832 - probe python.function.entry does not get hits (while .return does)
Summary: probe python.function.entry does not get hits (while .return does)
Status: RESOLVED NOTABUG
Alias: None
Product: systemtap
Classification: Unclassified
Component: runtime (show other bugs)
Version: unspecified
: P2 normal
Target Milestone: ---
Assignee: Unassigned
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2022-11-28 12:31 UTC by Martin Cermak
Modified: 2022-12-14 08:31 UTC (History)
0 users

See Also:
Host:
Target:
Build:
Last reconfirmed:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Cermak 2022-11-28 12:31:44 UTC
With both systemtap-4.8-1.fc38 and the upstream git commit 342e5ec5619066f227ff9c3a5c,
probe python.function.entry isn't getting hits, while respective .return prob gets hit just fine:

# cat test.py 
import random, time
print(random.random())
time.sleep(3)
# stap -we 'probe process("/usr/lib*/libpython*.so*").mark("function__return") {filename = user_string($arg1); if  (filename =~ "random") {println(filename) exit()}}' -c 'python3 ./test.py >/dev/null'
/usr/lib64/python3.11/random.py
# stap -we 'probe process("/usr/lib*/libpython*.so*").mark("function__entry") {filename = user_string($arg1); if  (filename =~ "random") {println(filename) exit()}}' -c 'python3 ./test.py >/dev/null'
# 
#

This is with python3-3.11.0-1.fc38.x86_64.
Comment 1 Martin Cermak 2022-12-12 12:11:02 UTC
SystemTap static markers are present in the built binary:

38 x86_64 # readelf -S /usr/lib64/libpython3.11.so.1.0 | grep .note.stapsdt
  [29] .note.stapsdt     NOTE             0000000000000000  0051eeb8
38 x86_64 # readelf -n /usr/lib64/libpython3.11.so.1.0 | fgrep -B2 -A2 function__
fgrep: warning: fgrep is obsolescent; using grep -F
  stapsdt              0x00000046       NT_STAPSDT (SystemTap probe descriptors)
    Provider: python
    Name: function__return
    Location: 0x0000000000184698, Base: 0x000000000035dce8, Semaphore: 0x000000000051eeb4
    Arguments: 8@%rbp 8@%r12 -4@%eax
  stapsdt              0x00000045       NT_STAPSDT (SystemTap probe descriptors)
    Provider: python
    Name: function__entry
    Location: 0x00000000001846d2, Base: 0x000000000035dce8, Semaphore: 0x000000000051eeb6
    Arguments: 8@%rbp 8@%r12 -4@%eax
38 x86_64 #

Systemtap can see them:

38 x86_64 # stap -L 'process("/usr/lib*/libpython*.so*").mark("*")'
process("/usr/lib64/libpython3.11.so.1.0").mark("audit") $arg1:long $arg2:long
process("/usr/lib64/libpython3.11.so.1.0").mark("function__entry") $arg1:long $arg2:long $arg3:long
process("/usr/lib64/libpython3.11.so.1.0").mark("function__return") $arg1:long $arg2:long $arg3:long
process("/usr/lib64/libpython3.11.so.1.0").mark("gc__done") $arg1:long
process("/usr/lib64/libpython3.11.so.1.0").mark("gc__start") $arg1:long
process("/usr/lib64/libpython3.11.so.1.0").mark("import__find__load__done") $arg1:long $arg2:long
process("/usr/lib64/libpython3.11.so.1.0").mark("import__find__load__start") $arg1:long
process("/usr/lib64/libpython3.11.so.1.0").mark("line") $arg1:long $arg2:long $arg3:long
38 x86_64 #
38 x86_64 #

Systemtap can hit them both

38 x86_64 #
38 x86_64 # stap -e 'probe process("/usr/lib64/libpython3.11.so.1.0").mark("function__return") {log(pp()) exit()}' -c 'python3 ./test.py'
process("/usr/lib64/libpython3.11.so.1.0").statement(0x184698)
0.0052528132240494685
38 x86_64 # stap -e 'probe process("/usr/lib64/libpython3.11.so.1.0").mark("function__entry") {log(pp()) exit()}' -c 'python3 ./test.py'
process("/usr/lib64/libpython3.11.so.1.0").statement(0x1846d2)
0.470956593448124
38 x86_64 #

The problem appears to be with arguments, specifically with filename = user_string($arg1); which in case of the .mark("function__entry") probe seems to give <frozen getpath> instead of the actual path /usr/lib64/python3.11/random.py

38 x86_64 # stap -we 'probe process("/usr/lib*/libpython*.so*").mark("function__entry") {filename = user_string($arg1); println(filename)}' -c 'python3 ./test.py >/dev/null'
<frozen getpath>
<frozen getpath>
<frozen _collections_abc>
<frozen _collections_abc>
<frozen _collections_abc>
38 x86_64 #
Comment 2 Martin Cermak 2022-12-12 12:22:51 UTC
Quick googling points me to https://github.com/python/cpython/issues/94526
Comment 3 Martin Cermak 2022-12-13 09:28:40 UTC
I've verified that the testcase/scenario *does* work with both GDB and systemtap with *python2*, and that the testcase *does not* work with both GDB and systemtap with *python3*:

# cat test.py 
import random, time
print(random.random())
# print(random.randrange(1,100))
time.sleep(3)
# 



# cat cmds 
# run program so that all .SO's load and so do the static markers
r
# list avail static markers
info probes stap python
# the following conditional breakpoint doesn't work, for some
# reason it fires always, regardless the condition
# b -probe-stap function__return if strstr(filename, "random")
# so instead of the conditional breakpoint, set up a set of
# commands to run on each breakpoint hit
b -probe-stap function__entry
commands 1
p (char*)$_probe_arg0
c
end
r
#


 

# gdb --command=cmds --batch --args python2 ./test.py | grep -F random
$706 = 0x7ffff79c3b94 "/usr/lib64/python2.7/random.py"
$723 = 0x7ffff79c3284 "/usr/lib64/python2.7/random.py"
$724 = 0x7ffff79c35f4 "/usr/lib64/python2.7/random.py"
$725 = 0x7ffff79c39b4 "/usr/lib64/python2.7/random.py"
$726 = 0x7ffff79bb324 "/usr/lib64/python2.7/random.py"
$727 = 0x7ffff79bb3c4 "/usr/lib64/python2.7/random.py"
# 




# gdb --command=cmds --batch --args python3 ./test.py | grep -F random
# 



# stap --poison-cache -we 'probe process("/usr/lib*/libpython*.so*").mark("function__entry") {filename = user_string($arg1); if  (filename =~ "random") {println(filename)}}' -c 'python2 ./test.py'
/usr/lib64/python2.7/random.py
0.366413745444
/usr/lib64/python2.7/random.py
/usr/lib64/python2.7/random.py
/usr/lib64/python2.7/random.py
/usr/lib64/python2.7/random.py
/usr/lib64/python2.7/random.py
# 



# stap --poison-cache -we 'probe process("/usr/lib*/libpython*.so*").mark("function__entry") {filename = user_string($arg1); if  (filename =~ "random") {println(filename)}}' -c 'python3 ./test.py'
0.6176074507358171
#
Comment 4 Martin Cermak 2022-12-13 16:22:31 UTC
After talking to the python folks, I've filed
https://bugzilla.redhat.com/show_bug.cgi?id=2152970
Comment 5 Martin Cermak 2022-12-14 08:31:30 UTC
Since this doesn't seem to be a systemtap problem, I'm closing this one.