Author dmalcolm
Recipients belopolsky, bretthoerner, chrismiles, danchr, dmalcolm, glyph, jbaker, jcea, laca, mjw, movement, rhettinger, robert.kern, ronaldoussoren, sirg3, skip.montanaro, twleung, wsanchez
Date 2010-02-26.20:41:42
SpamBayes Score 1.66533e-16
Marked as misclassified No
Message-id <1267216908.54.0.311408304236.issue4111@psf.upfronthosting.co.za>
In-reply-to
Content
At Red Hat we've done some work on this feature.  I'm sorry for not updating this issue, I was swamped with tasks both pre-PyCon and during the event; I did show the following to various folks at PyCon; I attempted to find Skip at PyCon but was unsuccessful)

Unfortunately I have two further versions of this patch for you :(

High level summary
------------------
SystemTap is a similar tool for DTrace, but for Linux.

At Red Hat we've been looking at implementing this using SystemTap.  SystemTap makes some attempts to be at least somewhat compatible with DTrace, and we are able to get the DTrace support to build against SystemTap.

I measured the performance and found that some versions of the patch impose a significant performance penalty.

We have a version of the patch that works with SystemTap on Linux, and appears not to impose a performance penalty for the cases I think are important (see notes below)

I have also ported the patch to Python 3 (I pass the strings back to the probe support as UTF-8 encoded)

I hope that there's enough commonality between the SystemTap and DTrace patches to permit common parts to be committed to Python, perhaps eventually supporting both.  Having said that, I don't have any systems that can run DTrace.

I've chosen to build the upcoming Fedora 13's Python 2 and Python 3 rpms with this support enabled (I'm a Python guy, not a SystemTap guy, FWIW, but we have a strong in-house SystemTap team).  We've been tracking this downstream for Fedora, our detailed discussions are within this bug in our downstream tracker:
https://bugzilla.redhat.com/show_bug.cgi?id=545179
along with status:
  https://fedoraproject.org/wiki/Features/SystemtapStaticProbes#Python
and documentation:
  https://fedoraproject.org/wiki/Features/SystemtapStaticProbes#Python_2


Details
-------
SystemTap supplies a "dtrace" executable implemented in Python, which mimics the "dtrace" binary.
$ which dtrace
/usr/bin/dtrace
$ file $(which dtrace)
/usr/bin/dtrace: python script text executable
$ dtrace --help
Usage /usr/bin/dtrace [--help] [-h | -G] [-C [-I<Path>]] -s File.d [-o <File>]
Where -h builds a systemtap header file from the .d file
      -C when used with -h, also run cpp preprocessor
      -o specifies an explicit output file name,
         the default for -G is file.o and -h is file.h
      -I when running cpp pass through this -I include Path
      -s specifies the name of the .d input file
      -G builds a stub file.o from file.d,
         which is required by some packages that use dtrace.

I'm attaching a version of the patch against svn trunk.

This adds a "--with-dtrace" configuration option (I filed issue 7997 to better document how to do this).

Tested on a Fedora 12 box and works, with:
systemtap-1.1-2.fc12.i686
systemtap-sdt-devel-1.1-1.fc12.i686
systemtap-runtime-1.1-2.fc12.i686
kernel-PAE-2.6.31.12-174.2.3.fc12.i686
kernel-PAE-devel-2.6.31.12-174.2.3.fc12.i686
kernel-PAE-debuginfo-2.6.31.12-174.2.3.fc12.i686
kernel-headers-2.6.31.12-174.2.3.fc12.i686
kernel-debuginfo-common-i686-2.6.31.12-174.2.3.fc12.i686
kernel-firmware-2.6.31.12-174.2.3.fc12.noarch

Upon building --with-dtrace (but actually with systemtap), the linked binary containing ceval.o should contain a "probes" section (the following is a statically-linked build, hence the probes are in "./python"):

$ eu-readelf -S ./python | grep probes
[25] .probes              PROGBITS     081f9d28 1b0d28 000054  0 WA     0   0  8

$ eu-readelf -x .probes python

Hex dump of section [25] '.probes', 84 bytes at offset 0x1b0d28:
  0x00000000 66756e63 74696f6e 5f5f656e 74727900 function__entry.
  0x00000010 50524231 00000000 289d1f08 00000000 PRB1....(.......
  0x00000020 a50e0f08 00000000 66756e63 74696f6e ........function
  0x00000030 5f5f7265 7475726e 00000000 50524231 __return....PRB1
  0x00000040 509d1f08 00000000 1a0f0f08 00000000 P...............
  0x00000050 00000000                            ....

The above contains locations of "nop" instructions within the binary.  Systemtap generates kernel modules, and it uses this information to generate modules that monkeypatch the "nop" instruction at runtime to jump to code that gathers the pertinent information (filename, lineno etc) and returns that information to the kernel, and thus back to the user-space probe process.

Example of use
--------------
Here's an example of running regrtest whilst probing python to see function call and return during a run of the regression test suite (all in one shell command; obviously it would be saner to split the systemtap probe into a separate function):

[david@brick trunk-stap]$ stap -v -e'probe python.function.entry = process("./python").mark("function__entry")
{
    filename = user_string($arg1);
    funcname = user_string($arg2);
    lineno = $arg3;
}
probe python.function.return = process("./python").mark("function__return")
{
    filename = user_string($arg1);
    funcname = user_string($arg2);
    lineno = $arg3;
}
probe python.function.entry { printf("%s => %s in %s:%d\n", thread_indent(1), funcname, filename, lineno); }

probe python.function.return {printf("%s <= %s in %s:%d\n", thread_indent(-1), funcname, filename, lineno);}' \
-c "./python Lib/test/regrtest.py"

Output is as follow (note that I used -v to get verbose info on systemtap's passes):
Pass 1: parsed user script and 65 library script(s) using 20132virt/12268res/2052shr kb, in 220usr/10sys/242real ms.
Pass 2: analyzed script: 2 probe(s), 12 function(s), 2 embed(s), 2 global(s) using 24868virt/14788res/3392shr kb, in 20usr/10sys/37real ms.
Pass 3: using cached /home/david/.systemtap/cache/26/stap_2689ea1aadf52992794511e0d6996aca_5352.c
Pass 4: using cached /home/david/.systemtap/cache/26/stap_2689ea1aadf52992794511e0d6996aca_5352.ko
Pass 5: starting run.
     0 python(6769): => <module> in /home/david/coding/python-svn/trunk-stap/Lib/site.py:59
  1063 python(6769):  => <module> in /home/david/coding/python-svn/trunk-stap/Lib/os.py:22
  2510 python(6769):   => <module> in /home/david/coding/python-svn/trunk-stap/Lib/posixpath.py:11
  2756 python(6769):    => <module> in /home/david/coding/python-svn/trunk-stap/Lib/stat.py:4
  2792 python(6769):    <= <module> in /home/david/coding/python-svn/trunk-stap/Lib/stat.py:94
  3015 python(6769):    => <module> in /home/david/coding/python-svn/trunk-stap/Lib/genericpath.py:5
  3051 python(6769):    <= <module> in /home/david/coding/python-svn/trunk-stap/Lib/genericpath.py:85
  3713 python(6769):    => <module> in /home/david/coding/python-svn/trunk-stap/Lib/warnings.py:1
  3948 python(6769):     => <module> in /home/david/coding/python-svn/trunk-stap/Lib/linecache.py:6
  3984 python(6769):     <= <module> in /home/david/coding/python-svn/trunk-stap/Lib/linecache.py:68
(etc)

Performance
-----------
There are four cases here from a performance perspective:
(a) the source code without the patch
(b) the source code with the patch, configured --without-dtrace
(c) the source code with the patch, configured --with-dtrace, but without any "live" probes using the static marker
(d) the source code with the patch, configured --with-dtrace, with one or more "live" probes using the static marker

The performance goals I've been working towards are:
  - that (a) and (b) should have identical behavior, and
  - that (b) and (c) should have no significant performance differences i.e. having the markers compiled in shouldn't cost anything (as a packager of Python I want to be able to supply a common build, and the vast majority of my users won't be using the markers)
  - that it's acceptable for (d) to have a moderate performance cost compared to (c)

I used the unladen-swallow benchmark suite to examine performance.  

Our initial version of the patch (based on http://bugs.python.org/file12861/dtrace.diff ) showed a significant performance penalty for case (c) relative to case (b): 5-14% additional time being taken on most benchmarks, in rough (but, I believe, credible) tests.  Some notes on this can be seen at https://bugzilla.redhat.com/show_bug.cgi?id=545179#c12

I believe this regression is due to the generation and storing of f_calllineno at every frame entry.

We removed this and further benchmarking showed an insignificant performance difference between (b) and (c), though I wasn't as rigorous as I could have been with these benchmarks.  Some notes on this can be seen at https://bugzilla.redhat.com/show_bug.cgi?id=545179#c14

Case (d) probably has a significant penalty relative to (c), but I don't regard that as a blocker.  I haven't yet attempted to measure the performance impact of live probes.

Other issues
------------
If I'm reading things correctly, the marker is actually instrumenting frame entry and exit, not function entry and exit, so it probably needs renamimg.

There are many other possible static markers that could be implemented, but it's probably easiest to do this one first, then add more later (We brainstormed some ideas here: https://fedoraproject.org/wiki/Features/SystemtapStaticProbes#Python )

In my Fedora rpm packages I also supply a "tap set" (a kind of SystemTap module, for code reuse), that modularizes parts of the tracing above to minimize boilerplate when writing a .stp script that uses the markers.
This can be seen here: http://cvs.fedoraproject.org/viewvc/rpms/python/devel/libpython.stp?view=markup

I also include an example script, which can be seen here:
http://cvs.fedoraproject.org/viewvc/rpms/python/devel/systemtap-example.stp?view=markup


Hope this is helpful; sorry if this is muddying the waters further :(
Dave
History
Date User Action Args
2010-02-26 20:41:48dmalcolmsetrecipients: + dmalcolm, skip.montanaro, rhettinger, jcea, ronaldoussoren, belopolsky, wsanchez, movement, glyph, bretthoerner, laca, twleung, jbaker, robert.kern, sirg3, chrismiles, danchr, mjw
2010-02-26 20:41:48dmalcolmsetmessageid: <1267216908.54.0.311408304236.issue4111@psf.upfronthosting.co.za>
2010-02-26 20:41:47dmalcolmlinkissue4111 messages
2010-02-26 20:41:42dmalcolmcreate