Bug 546006 - Incorrect values for parameters using process().function()
Incorrect values for parameters using process().function()
Status: CLOSED CURRENTRELEASE
Product: Fedora
Classification: Fedora
Component: systemtap (Show other bugs)
12
All Linux
low Severity medium
: ---
: ---
Assigned To: Frank Ch. Eigler
Fedora Extras Quality Assurance
:
Depends On:
Blocks: StapStaticProbesF13
  Show dependency treegraph
 
Reported: 2009-12-09 14:19 EST by Dave Malcolm
Modified: 2010-02-21 13:02 EST (History)
6 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2010-02-21 13:02:42 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Dave Malcolm 2009-12-09 14:19:17 EST
Description of problem:
I'm attempting to use systemtap to probe Python's usage of the heap, but ran into an issue with getting the args to the various user-space functions.

Here's a (very) simplified version of the script I'm trying (python-mem.stp):

  probe process("/usr/lib/libpython2.6.so.1.0").function("PyObject_Malloc") {
    printf("PyObject_Malloc(%i)\n", $nbytes);
  }

with the hope of probing this function inside libpython2.6.so.1.0:

  void * PyObject_Malloc(size_t nbytes) {
     (snip large, complicated implementation, using arenas on top of malloc)
  }

I try running it thus:
stap -v python-mem.stp -c "python -c 'import gtk; import dbus'"

The output is a series of lines:
stap -v python-mem.stp -c "python -c 'import gtk; import dbus'"
Pass 1: parsed user script and 59 library script(s) in 210usr/20sys/233real ms.
Pass 2: analyzed script: 1 probe(s), 1 function(s), 0 embed(s), 0 global(s) in 30usr/0sys/45real ms.
Pass 3: translated to C into "/tmp/stapw9tHdC/stap_7df6edc8c0d40522be12c31a11cb120d_1331.c" in 110usr/0sys/125real ms.
Pass 4, preamble: verifying that SystemTap's version of uprobes is up to date.
Pass 4: compiled C into "stap_7df6edc8c0d40522be12c31a11cb120d_1331.ko" in 2530usr/490sys/3208real ms.
Pass 5: starting run.
PyObject_Malloc(123)
PyObject_Malloc(123)
PyObject_Malloc(123)
PyObject_Malloc(123)
PyObject_Malloc(123)
PyObject_Malloc(123)
(etc, all lines have value 123)

Version-Release number of selected component (if applicable):
$ rpm -qa systemtap\* kernel\* python python-libs python-debuginfo | sort
kernel-debuginfo-common-i686-2.6.31.6-145.fc12.i686
kernel-firmware-2.6.31.6-145.fc12.noarch
kernel-headers-2.6.31.6-145.fc12.i686
kernel-PAE-2.6.30.9-90.fc11.i686
kernel-PAE-2.6.30.9-96.fc11.i686
kernel-PAE-2.6.31.6-145.fc12.i686
kernel-PAE-debuginfo-2.6.31.6-145.fc12.i686
kernel-PAE-devel-2.6.30.9-90.fc11.i686
kernel-PAE-devel-2.6.30.9-96.fc11.i686
kernel-PAE-devel-2.6.31.6-145.fc12.i686
python-2.6.2-2.fc12.i686
python-debuginfo-2.6.2-2.fc12.i686
python-libs-2.6.2-2.fc12.i686
systemtap-1.0-2.fc12.i686
systemtap-runtime-1.0-2.fc12.i686
systemtap-sdt-devel-1.0-2.fc12.i686

How reproducible:
100% on this box; I'm also sometimes seeing error messages in pass 1 of the form:
  semantic error: No cfa_ops supplied, but needed by DW_OP_call_frame_cfa
when I make the script more complex; should I file that as a separate bug?

Steps to Reproduce:
1. as above
  
Actual results:
All lines are output with "123" as the value

Expected results:
Varying values, reflecting the sizes of the allocations, allowing me to get useful insight into how Python is using the heap.
Comment 1 Frank Ch. Eigler 2009-12-09 14:34:45 EST
This could be related to systemtap PR 10601, which we're expecting to fix for an impending next release of systemtap.
Comment 2 Dave Malcolm 2009-12-10 11:12:02 EST
> This could be related to systemtap PR 10601, which we're expecting to fix for
> an impending next release of systemtap.  
URL: http://sourceware.org/bugzilla/show_bug.cgi?id=10601
Comment 3 Dave Malcolm 2010-01-12 18:17:47 EST
I notice that you marked http://sourceware.org/bugzilla/show_bug.cgi?id=10601 as RESOLVED FIXED on 2009-12-21 - thanks.

Are these fixes in rawhide yet?  (pretty-please!)
Comment 4 Mark Wielaard 2010-01-18 05:50:40 EST
(In reply to comment #3)
> I notice that you marked http://sourceware.org/bugzilla/show_bug.cgi?id=10601
> as RESOLVED FIXED on 2009-12-21 - thanks.
> 
> Are these fixes in rawhide yet?  (pretty-please!)    

Yes, they should be available with systemtap-1.1-1.fc13.
This also provides the systemtap dtrace -I script support.
Comment 5 Mark Wielaard 2010-01-18 06:25:11 EST
(In reply to comment #0)
> I'm also sometimes seeing error messages in pass 1 of the
> form:
>   semantic error: No cfa_ops supplied, but needed by DW_OP_call_frame_cfa
> when I make the script more complex; should I file that as a separate bug?

Yes please, if you see it after updating to systemtap-1.1.
There has been one bug fix for 1.1 that addresses one case of DW_OP_call_frame_cfa not being found, but there seems to be some other issue lurking out there. If you get anything with a good reproducer that would be very appreciated.
Comment 6 Dave Malcolm 2010-01-19 16:38:57 EST
> > I'm also sometimes seeing error messages in pass 1 of the
> > form:
> >   semantic error: No cfa_ops supplied, but needed by DW_OP_call_frame_cfa
> > when I make the script more complex; should I file that as a separate bug?

> Yes please, if you see it after updating to systemtap-1.1.
Still seeing this with 1.1; filed as bug 556944
Comment 7 Mark Wielaard 2010-02-19 04:38:58 EST
With systemtap-1.1-2.fc12.i686 I am seeing:

$ stap -e 'probe process("/usr/lib/libpython2.6.so.1.0").function("PyObject_Malloc") {    printf("PyObject_Malloc(%i)\n", $nbytes);  }' -c "python -c 'import gtk; import dbus'"
PyObject_Malloc(24)
PyObject_Malloc(35)
PyObject_Malloc(136)
PyObject_Malloc(31)
PyObject_Malloc(136)
PyObject_Malloc(31)
PyObject_Malloc(31)
PyObject_Malloc(32)
PyObject_Malloc(35)
PyObject_Malloc(36)
[... lots of different numbers ...]

Do these numbers make sense now?
Comment 8 Dave Malcolm 2010-02-21 12:04:45 EST
Thanks!  This is now working well

systemtap-1.1-2.fc12.i686
systemtap-sdt-devel-1.1-1.fc12.i686
systemtap-runtime-1.1-2.fc12.i686

The numbers below appear credible; here's an example of the 3 levels of memory allocations, running:  python -c"pass"; hope to use this to improve Python's heap-usage behavior.

PyObject_Malloc calls:
value |-------------------------------------------------- count
    0 |                                                       0
    1 |                                                      35
    2 |@                                                    322
    4 |@                                                    233
    8 |                                                      90
   16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@          8855
   32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  10481
   64 |@@@@@@@@                                            1850
  128 |@@                                                   588
  256 |@@                                                   428
  512 |@@                                                   538
 1024 |                                                      16
 2048 |                                                       6
 4096 |                                                       1
 8192 |                                                       1
16384 |                                                       0
32768 |                                                       0

PyMem_Malloc calls:
value |-------------------------------------------------- count
    1 |                                                    0
    2 |                                                    0
    4 |@@@@@@@@@@@                                        11
    8 |                                                    0
   16 |@@@@@@@@@@@@@@@@@@@@@@                             22
   32 |@@@@@@@@@@@@@@@                                    15
   64 |                                                    0
  128 |@@@@@                                               5
  256 |                                                    0
  512 |@@@@@@@@                                            8
 1024 |                                                    0
 2048 |                                                    0
 4096 |                                                    0
 8192 |@@@@@@@@@@@@@@@@                                   16
16384 |                                                    0
32768 |                                                    0

malloc calls:
  value |-------------------------------------------------- count
      0 |                                                     0
      1 |                                                     1
      2 |                                                     1
      4 |@@@@@@@@@                                          179
      8 |@@@@@@@@@@@@@@@                                    300
     16 |@@@@@@@@@@@@@@@@@@@@@@@                            451
     32 |@@@@@@                                             127
     64 |@                                                   19
    128 |@                                                   23
    256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@    905
    512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                     576
   1024 |@@@@@@@@@@                                         205
   2048 |                                                     8
   4096 |                                                    16
   8192 |@                                                   32
  16384 |@                                                   20
  32768 |                                                     4
  65536 |                                                     1
 131072 |                                                     0
 262144 |                                                     3
 524288 |                                                     0
1048576 |                                                     0

Note You need to log in before you can comment on or make changes to this bug.