I want this to 3.3. I will concentrate in DTrace under Solaris and derivatives, for now. No SystemTap.

Original details, useful for context: issue4111.

My reference is going to be Solaris/OpenIndiana patches for Python DTrace support.

Based on work done by skip.montanaro for issue4111.

05fde8943685.diff compiles correctly under Solaris 10 & derivatives, both in 32 and 64 bits.

I am working on 2.7 because I consider this feature important enough for providing a patch against 2.7, available to interested users. Of course, the plan is to integrate in 3.3 natively.

Currently the patch define two probes: function__entry and function__return. Both have three parameters: source code file, function and linenumber.

The code doesn't work under MacOS, I guess, and I can't help there.

New changeset, with testsuite added.

Compile the code adding "--with-dtrace" to your "configure" command. After compiling, test the code with

"""
LD_LIBRARY_PATH=current_path
export LD_LIBRARY_PATH

./python Lib/test/regrtest.py -v test_dtrace.py

"""

It is currently working in Solaris 10, both in 32 and 64 bits.

If you are inside a Solaris/OpenIndiana Zone, the zone *MUST* have dtrace usermode permissions. If not, you can not use dtrace inside the zone and, then, the test will fail.

> LD_LIBRARY_PATH=current_path
> export LD_LIBRARY_PATH

Why do you need LD_LIBRARY_PATH?

> If you are inside a Solaris/OpenIndiana Zone, the zone *MUST* have
> dtrace usermode permissions. If not, you can not use dtrace inside the
> zone and, then, the test will fail.

If there aren't enough permissions, the tests should be skipped rather
than fail.

While using LD_LIBRARY_PATH might be ok for a quick run by hand,
it's preferable to use an RPATH when linking for more long term
usages.

The LD_LIBRARY_PATH is because I am compiling Python as a shared lib and, of course, I am not installing the development version in the usual system path.

That is, it is not a requirement for this project, but an easy to follow procedure for unexperienced betatesters.

About the permissions, the situation is messy because under Solaris a regular user can not run dtrace unless special permissions be assigned to her. The situation is something like this: (talking about Solaris 10):

* Global Zone:
 - root: dtrace works.
 - Regular user: dtrace is going to show a "permission denied" error, unless an admin had set dtrace user/proc permissions to him. If that is the case, it works.

* Non Global Zone:
 - root: dtrace seems to work, but no probes can be found unless special dtrace user/proc permissions are assigned to the zone.
 - regular user: dtrace is going to show a "permission denied" error, unless an admin had set dtrace user/proc permissions to him. In that case, it will behave like "root". That is, no probes found unles the zone have the right capabilities.

The permission denied error can be easily detected and managed, but the "silent" error is not distinguible of this project not working. I am thinking about trying first an "always present" well known probe, to detect when the kernel is activelly ignoring dtrace instead of giving a clear permission error.

I have requested to the sysadmins of my OpenIndiana buildbots to activate dtrace (of user code) in my zone, so I can evaluate the behaviour under OpenIndiana/Illumos.

A couple of details I want to document here, to remember then and to ask for advice:

- I have added a "sys.trace_capabilities", so a program can know if any system-trace functionality is compiled in. Current values are "None" and "("dtrace", "Sun")". Maybe create a new "dtrace" module could be appropiate, instead, with "dtrace.supported=True/False", but I am thinking about future MacOS probes, Linux "systemtap" probes, etc.

- Current code only traces function calls *TO* Python code. If the function calls is to C code (os.getpid(), for instance), the call is not visible. I think this is a major deficience, apparently shared by all the previous attempts I have seen (including official Sun probes).

New changeset: 7c1b63f949e7.diff

Now I detect lacking of dtrace privileges, both in the global zone and in a non-global zone.

For that, I verify that the process can actually insert a C-entry point probe in a well known function: PyEval_EvalCode. This should work ALWAYS, even if the dtrace instrumentation provided by this fails miserably.

We have to remember if we change that function name, someday...

> - I have added a "sys.trace_capabilities", so a program can know if any
> system-trace functionality is compiled in. Current values are "None"
> and "("dtrace", "Sun")".

I'm not sure "Sun" is the right name here.  I'd say either "SunOS" or "Solaris" (or the lowercase of either).  "Sun" typically refers to Sun hardware, which isn't relevant here, and the company, which doesn't exist anymore, also isn't particularly relevant.

New changeset.

New probes:

- "gc-start", "gc-done": Signal Garbage Collection operations. The first get the generation to scan, the second gets the number of objects collected.

- "line": Called in every Python line. Parameters: module, function, linenumber.

- "instance-new-start", "instance-new-done": information about instance creation.

 - Old style classes: get the name of the class, and the name of the module.

 - New style classes: get the name of the class and, IF WE CAN, the name of the module. This is not working 100%.

- "instance-delete-start", "instance-delete-done": information about instance deletion.

 - Old style classes: get the name of the class, and the name of the module.

 - New Style classes: Not working yet.

Shortcomings:

- We don't trace new style instances deletion yet.

- We don't trace most C objects creation/deletion.

- When displaying newstyle instances, the module parameter can be incorrect, for internal types.

 - The "line" probe is called again in the first and last line of a loop when the loop finishes.

- Line tracing is more efficient and corretly skip the last body line when the loop is done.

- Trace new style classes deletion.

- When creating new style classes, ignore internal classes. Show only user defined classes.

- Solve a possible crash if we are tracing "instance-delete-done" and the deleted instance cascades a class delete (if it was the last reference to the class).

- Added documentación.

- Change "sys.trace_capabilities" to an external "dtrace" extension module.

I don't care about Sun/Apple compatibility. The new probes are far more extensive, and they should be the new standard.

The code is tested under Solaris 10 x86 and x86-64. Could someone possibly test under Solaris SPARC 32/64 bits, and other platforms with dtrace support, like *bsd, mac, etc?.

PS: This code is for 2.7, because I think it is important to have a patch for interested parties to include in their python distributions. The plan is to integrate natively in 3.3.

Preview of the 3.3 patch. Includes work from issue #13488.

Work to do:

- "line" probe.

- "jstack()" helper.

- Instance names work, but using internal undocumented API. Change that. Probably keeping an "encoded" version of the name for each type. Memory use increase should be linear with number of types, not number of instances. Think about it.

- Verify memory use increase with "co->co_filename_encoded" and "co->co_name_encoded".

New 3.3 version.

- Use the cached UTF8 of strings inside the interpreter, instead of managing the details manually.

- "line" probe works, even with "computed-gotos" optimization.

The only missing feature now, compared with 2.7 version, is the "stack" helper. Working on it.

Please let us know when you consider your patch ready for review.

Stack trace helper done for the case that the filenames and the function names are ascii. Pending the case we have latin1 and unicode characters.

In the process I have learned more about the implementation details of PEP-393 that I would like to know :-).

Code ready for general testing. I want to do same changes before asking for review.

I know that 2.7 patch is not going to be integrated in mainline but would you consider reviewing it?. I would adopt the changes proposed, and integrate them also in 3.3 version, before the formal review.

> I know that 2.7 patch is not going to be integrated in mainline but would you consider reviewing it?

I personally won't. If there are things that will apply to 2.7 as well,
you surely can backport them also, no?

The stack walker helper now supports unicode too. This was quite difficult!.

The patch is functionally complete.

Current patch is pretty final. It was easy and painless EXCEPT the stackhelper, because the "idea" of "PyCompactUnicodeObject" that GCC and DTRACE have are different. Current code includes a couple of "magic numbers". This can be fragile. But if it breaks, the only missing functionality would be the augmented stack dump. No crashed, because DTRACE probes are safe (for the program being monitored).

I guess the best idea would be to generate a ".h" at compile time, with the right magic constants.

I have tried to create global variables and import them from the stackhelper. That works... unless you use the "-c" DTrace argument. I guess I am hitting some bug in DTrace.

Pending: performance analysis. The performance hit should be very small.

Please, do a preliminar review.

The patch works for systemtap except for one minor nit.  pydtrace.h, created by stap from pydtrace.d, is stap specific.  Could pydtrace.h not be included in <srcdir>/Include so that it is always created at build time in <blddir>/Include?   If PyEval_GetFrame() were passed via function__entry then stap would be able to do something akin to what the ustack helper phelper.d is doing.

Alan, I would open a new issue tracking this one and posting a patch there, if I were you.

Previous DTRACE attempts failed because trying to make everybody happy. I don't want to repeat the mistake.

I am open to modify this code to satisfy systemtap *AFTER* this feature is committed. Same with DTRACE particularities in FreeBSD, MacOS X, etc. You can be sure about my support.

Feel free to clone my mercurial repository and track my code.

Pending work yet: (documented to avoid forgeting it)

- Performance hit because trying to determine the source line in each function call. To be solved with ¿tolerable? memory overhead. Would be acceptable to sacrifice x2/x4 time the pyc filesize (in memory) in order to avoid any runtime performance hit?. That is, a million bytecodes (not a bad program size) could need 2/4 MB. I think it is a good investment if DTRACE becomes performance-transparent.

- Build procedure is flaky. I am asking DTrace developers.

- DTRACE/GCC offset/bitmasks doesn't coincide. Instead of wiring offsets manually, they should be detected at compile time, automatically.

- Add new probes. Suggestions?. What do you want to instrumentalize?. I am thinking about the GIL, module import

- Try the code with "clang" instead of GCC.

- Address pending review comments done by Martin v. Löwis.

- Use PEP 3155.

- Trace C function calls/returns, not only Python ones. The problem here is to know the name of the function, because we can call it in a million different ways. Memorizing the last attribute lookuped is not enough. It seems necessary to memorize some extra metadata at C import.

Performance report for current 3.3 tip, using "pybench".

******** BASELINE: (original version without DTRACE patch)

-------------------------------------------------------------------------------
PYBENCH 2.1
-------------------------------------------------------------------------------
* using CPython 3.3.0a0 (default:70ba352f9586, Dec 11 2011, 22:46:09) [GCC 4.6.2]
* disabled garbage collection
* system check interval set to maximum: 2147483647
* using timer: time.time

Calibrating tests. Please wait... done.

Running 10 round(s) of the suite at warp factor 10:

* Round 1 done in 4.457 seconds.
* Round 2 done in 4.466 seconds.
* Round 3 done in 4.438 seconds.
* Round 4 done in 4.503 seconds.
* Round 5 done in 4.519 seconds.
* Round 6 done in 4.514 seconds.
* Round 7 done in 4.460 seconds.
* Round 8 done in 4.455 seconds.
* Round 9 done in 4.477 seconds.
* Round 10 done in 4.547 seconds.

-------------------------------------------------------------------------------
Benchmark: 2011-12-11 22:50:16
-------------------------------------------------------------------------------

    Rounds: 10
    Warp:   10
    Timer:  time.time

    Machine Details:
       Platform ID:    SunOS-5.10-i86pc-i386-32bit-ELF
       Processor:      i386
    
    Python:
       Implementation: CPython
       Executable:     /home/python/cpython/Tools/pybench/../../python
       Version:        3.3.0a0
       Compiler:       GCC 4.6.2
       Bits:           32bit
       Build:          Dec 11 2011 22:46:09 (#default:70ba352f9586)
       Unicode:        UCS4


Test                             minimum  average  operation  overhead
-------------------------------------------------------------------------------
          BuiltinFunctionCalls:     79ms     82ms    0.16us    0.291ms
           BuiltinMethodLookup:     58ms     59ms    0.06us    0.342ms
                 CompareFloats:     58ms     59ms    0.05us    0.390ms
         CompareFloatsIntegers:    114ms    118ms    0.13us    0.304ms
               CompareIntegers:     89ms     91ms    0.05us    0.589ms
        CompareInternedStrings:     72ms     75ms    0.05us    1.519ms
                  CompareLongs:     47ms     49ms    0.05us    0.340ms
                CompareStrings:     58ms     59ms    0.06us    1.013ms
    ComplexPythonFunctionCalls:     68ms     70ms    0.35us    0.501ms
                 ConcatStrings:     71ms     73ms    0.15us    0.560ms
               CreateInstances:    109ms    113ms    1.01us    0.456ms
            CreateNewInstances:     82ms     84ms    1.00us    0.364ms
       CreateStringsWithConcat:    107ms    111ms    0.11us    0.991ms
                  DictCreation:     55ms     57ms    0.14us    0.391ms
             DictWithFloatKeys:     82ms     84ms    0.09us    0.739ms
           DictWithIntegerKeys:     65ms     66ms    0.06us    0.992ms
            DictWithStringKeys:     58ms     59ms    0.05us    0.991ms
                      ForLoops:     63ms     65ms    2.59us    0.044ms
                    IfThenElse:     74ms     76ms    0.06us    0.739ms
                   ListSlicing:     46ms     47ms    3.39us    0.053ms
                NestedForLoops:     85ms     88ms    0.06us    0.003ms
      NestedListComprehensions:     86ms     88ms    7.33us    0.096ms
          NormalClassAttribute:    151ms    155ms    0.13us    0.529ms
       NormalInstanceAttribute:     86ms     87ms    0.07us    0.552ms
           PythonFunctionCalls:     65ms     66ms    0.20us    0.292ms
             PythonMethodCalls:     97ms    100ms    0.44us    0.184ms
                     Recursion:    114ms    116ms    2.33us    0.494ms
                  SecondImport:     70ms     72ms    0.72us    0.199ms
           SecondPackageImport:     70ms     73ms    0.73us    0.192ms
         SecondSubmoduleImport:    123ms    126ms    1.26us    0.192ms
       SimpleComplexArithmetic:     66ms     68ms    0.08us    0.391ms
        SimpleDictManipulation:    108ms    111ms    0.09us    0.493ms
         SimpleFloatArithmetic:     66ms     68ms    0.05us    0.591ms
      SimpleIntFloatArithmetic:     82ms     84ms    0.06us    0.589ms
       SimpleIntegerArithmetic:     82ms     85ms    0.06us    0.603ms
      SimpleListComprehensions:     71ms     74ms    6.18us    0.096ms
        SimpleListManipulation:     63ms     64ms    0.05us    0.646ms
          SimpleLongArithmetic:     60ms     62ms    0.09us    0.291ms
                    SmallLists:     86ms     89ms    0.13us    0.408ms
                   SmallTuples:     85ms     88ms    0.16us    0.455ms
         SpecialClassAttribute:    226ms    234ms    0.20us    0.547ms
      SpecialInstanceAttribute:     86ms     89ms    0.07us    0.533ms
                StringMappings:    277ms    286ms    1.13us    0.422ms
              StringPredicates:     96ms    100ms    0.14us    1.991ms
                 StringSlicing:     95ms     98ms    0.18us    0.836ms
                     TryExcept:     53ms     54ms    0.02us    0.741ms
                    TryFinally:     60ms     62ms    0.39us    0.390ms
                TryRaiseExcept:     35ms     38ms    0.60us    0.408ms
                  TupleSlicing:     75ms     78ms    0.30us    0.046ms
                   WithFinally:     86ms     89ms    0.55us    0.394ms
               WithRaiseExcept:     92ms     96ms    1.19us    0.512ms
-------------------------------------------------------------------------------
Totals:                           4353ms   4484ms


****** VERSION CALCULATING LINENUMBER IN EVERY FUNCTION CALL:

-------------------------------------------------------------------------------
PYBENCH 2.1
-------------------------------------------------------------------------------
* using CPython 3.3.0a0 (dtrace-issue13405:552edf5be75c, Dec 11 2011, 22:57:28) [GCC 4.6.2]
* disabled garbage collection
* system check interval set to maximum: 2147483647
* using timer: time.time

Calibrating tests. Please wait... done.

Running 10 round(s) of the suite at warp factor 10:

* Round 1 done in 4.880 seconds.
* Round 2 done in 4.876 seconds.
* Round 3 done in 4.899 seconds.
* Round 4 done in 4.887 seconds.
* Round 5 done in 4.872 seconds.
* Round 6 done in 4.913 seconds.
* Round 7 done in 4.888 seconds.
* Round 8 done in 4.865 seconds.
* Round 9 done in 4.888 seconds.
* Round 10 done in 4.864 seconds.

-------------------------------------------------------------------------------
Benchmark: 2011-12-11 22:58:51
-------------------------------------------------------------------------------

    Rounds: 10
    Warp:   10
    Timer:  time.time

    Machine Details:
       Platform ID:    SunOS-5.10-i86pc-i386-32bit-ELF
       Processor:      i386
    
    Python:
       Implementation: CPython
       Executable:     /home/python/cpython-jcea/Tools/pybench/../../python
       Version:        3.3.0a0
       Compiler:       GCC 4.6.2
       Bits:           32bit
       Build:          Dec 11 2011 22:57:28 (#dtrace-issue13405:552edf5be75c)
       Unicode:        UCS4


Test                             minimum  average  operation  overhead
-------------------------------------------------------------------------------
          BuiltinFunctionCalls:    129ms    131ms    0.26us    0.295ms
           BuiltinMethodLookup:     57ms     58ms    0.06us    0.346ms
                 CompareFloats:     61ms     62ms    0.05us    0.413ms
         CompareFloatsIntegers:    117ms    118ms    0.13us    0.295ms
               CompareIntegers:     90ms     90ms    0.05us    0.596ms
        CompareInternedStrings:     74ms     74ms    0.05us    1.520ms
                  CompareLongs:     53ms     53ms    0.05us    0.345ms
                CompareStrings:     57ms     58ms    0.06us    1.015ms
    ComplexPythonFunctionCalls:     84ms     85ms    0.43us    0.503ms
                 ConcatStrings:    105ms    106ms    0.21us    0.556ms
               CreateInstances:    117ms    118ms    1.05us    0.459ms
            CreateNewInstances:     87ms     88ms    1.05us    0.366ms
       CreateStringsWithConcat:    112ms    113ms    0.11us    0.995ms
                  DictCreation:     56ms     57ms    0.14us    0.395ms
             DictWithFloatKeys:     85ms     85ms    0.09us    0.746ms
           DictWithIntegerKeys:     68ms     68ms    0.06us    0.996ms
            DictWithStringKeys:     62ms     62ms    0.05us    0.997ms
                      ForLoops:     66ms     66ms    2.66us    0.045ms
                    IfThenElse:     80ms     80ms    0.06us    0.746ms
                   ListSlicing:     46ms     46ms    3.30us    0.058ms
                NestedForLoops:     88ms     89ms    0.06us    0.003ms
      NestedListComprehensions:     87ms     88ms    7.34us    0.103ms
          NormalClassAttribute:    152ms    154ms    0.13us    0.528ms
       NormalInstanceAttribute:     88ms     88ms    0.07us    0.530ms
           PythonFunctionCalls:     92ms     93ms    0.28us    0.295ms
             PythonMethodCalls:    113ms    114ms    0.51us    0.177ms
                     Recursion:    133ms    133ms    2.67us    0.496ms
                  SecondImport:     75ms     81ms    0.81us    0.194ms
           SecondPackageImport:     79ms     83ms    0.83us    0.195ms
         SecondSubmoduleImport:    136ms    139ms    1.39us    0.195ms
       SimpleComplexArithmetic:     69ms     69ms    0.08us    0.398ms
        SimpleDictManipulation:    156ms    158ms    0.13us    0.517ms
         SimpleFloatArithmetic:     68ms     68ms    0.05us    0.596ms
      SimpleIntFloatArithmetic:     83ms     83ms    0.06us    0.595ms
       SimpleIntegerArithmetic:     82ms     83ms    0.06us    0.594ms
      SimpleListComprehensions:     72ms     75ms    6.24us    0.097ms
        SimpleListManipulation:     96ms     97ms    0.08us    0.648ms
          SimpleLongArithmetic:     61ms     62ms    0.09us    0.295ms
                    SmallLists:    105ms    107ms    0.16us    0.395ms
                   SmallTuples:     90ms     92ms    0.17us    0.445ms
         SpecialClassAttribute:    223ms    226ms    0.19us    0.532ms
      SpecialInstanceAttribute:     87ms     88ms    0.07us    0.536ms
                StringMappings:    293ms    294ms    1.17us    0.426ms
              StringPredicates:    144ms    145ms    0.21us    1.833ms
                 StringSlicing:     94ms     95ms    0.17us    0.832ms
                     TryExcept:     59ms     59ms    0.03us    0.746ms
                    TryFinally:     89ms     90ms    0.56us    0.396ms
                TryRaiseExcept:     40ms     41ms    0.64us    0.395ms
                  TupleSlicing:     76ms     77ms    0.29us    0.042ms
                   WithFinally:     89ms     91ms    0.57us    0.397ms
               WithRaiseExcept:    101ms    103ms    1.29us    0.496ms
-------------------------------------------------------------------------------
Totals:                           4824ms   4883ms


****** CURRENT DTRACE PATCH, sacrifying memory for speed:

-------------------------------------------------------------------------------
PYBENCH 2.1
-------------------------------------------------------------------------------
* using CPython 3.3.0a0 (dtrace-issue13405:43d1a819a63d, Dec 11 2011, 22:40:40) [GCC 4.6.2]
* disabled garbage collection
* system check interval set to maximum: 2147483647
* using timer: time.time

Calibrating tests. Please wait... done.

Running 10 round(s) of the suite at warp factor 10:

* Round 1 done in 4.581 seconds.
* Round 2 done in 4.527 seconds.
* Round 3 done in 4.591 seconds.
* Round 4 done in 4.563 seconds.
* Round 5 done in 4.516 seconds.
* Round 6 done in 4.528 seconds.
* Round 7 done in 4.555 seconds.
* Round 8 done in 4.535 seconds.
* Round 9 done in 4.524 seconds.
* Round 10 done in 4.528 seconds.

-------------------------------------------------------------------------------
Benchmark: 2011-12-11 22:53:33
-------------------------------------------------------------------------------

    Rounds: 10
    Warp:   10
    Timer:  time.time

    Machine Details:
       Platform ID:    SunOS-5.10-i86pc-i386-32bit-ELF
       Processor:      i386
    
    Python:
       Implementation: CPython
       Executable:     /home/python/cpython-jcea/Tools/pybench/../../python
       Version:        3.3.0a0
       Compiler:       GCC 4.6.2
       Bits:           32bit
       Build:          Dec 11 2011 22:40:40 (#dtrace-issue13405:43d1a819a63d)
       Unicode:        UCS4


Test                             minimum  average  operation  overhead
-------------------------------------------------------------------------------
          BuiltinFunctionCalls:     78ms     79ms    0.16us    0.304ms
           BuiltinMethodLookup:     57ms     57ms    0.05us    0.356ms
                 CompareFloats:     60ms     61ms    0.05us    0.408ms
         CompareFloatsIntegers:    115ms    116ms    0.13us    0.304ms
               CompareIntegers:     90ms     91ms    0.05us    0.614ms
        CompareInternedStrings:     75ms     75ms    0.05us    1.552ms
                  CompareLongs:     53ms     54ms    0.05us    0.356ms
                CompareStrings:     57ms     59ms    0.06us    1.040ms
    ComplexPythonFunctionCalls:     74ms     76ms    0.38us    0.513ms
                 ConcatStrings:     70ms     73ms    0.15us    0.564ms
               CreateInstances:    113ms    116ms    1.04us    0.464ms
            CreateNewInstances:     85ms     87ms    1.03us    0.372ms
       CreateStringsWithConcat:    110ms    113ms    0.11us    1.030ms
                  DictCreation:     59ms     60ms    0.15us    0.406ms
             DictWithFloatKeys:     85ms     87ms    0.10us    0.770ms
           DictWithIntegerKeys:     70ms     70ms    0.06us    1.029ms
            DictWithStringKeys:     62ms     63ms    0.05us    1.029ms
                      ForLoops:     67ms     67ms    2.69us    0.046ms
                    IfThenElse:     79ms     80ms    0.06us    0.770ms
                   ListSlicing:     46ms     46ms    3.30us    0.057ms
                NestedForLoops:     88ms     89ms    0.06us    0.003ms
      NestedListComprehensions:     88ms     90ms    7.46us    0.100ms
          NormalClassAttribute:    155ms    157ms    0.13us    0.537ms
       NormalInstanceAttribute:     88ms     89ms    0.07us    0.540ms
           PythonFunctionCalls:     71ms     72ms    0.22us    0.305ms
             PythonMethodCalls:     98ms    100ms    0.44us    0.180ms
                     Recursion:    123ms    125ms    2.50us    0.512ms
                  SecondImport:     72ms     73ms    0.73us    0.210ms
           SecondPackageImport:     72ms     74ms    0.74us    0.210ms
         SecondSubmoduleImport:    126ms    129ms    1.29us    0.210ms
       SimpleComplexArithmetic:     68ms     69ms    0.08us    0.408ms
        SimpleDictManipulation:    117ms    118ms    0.10us    0.516ms
         SimpleFloatArithmetic:     66ms     67ms    0.05us    0.615ms
      SimpleIntFloatArithmetic:     82ms     82ms    0.06us    0.615ms
       SimpleIntegerArithmetic:     82ms     84ms    0.06us    0.614ms
      SimpleListComprehensions:     73ms     75ms    6.24us    0.104ms
        SimpleListManipulation:     64ms     65ms    0.06us    0.666ms
          SimpleLongArithmetic:     61ms     62ms    0.09us    0.304ms
                    SmallLists:     87ms     89ms    0.13us    0.406ms
                   SmallTuples:     84ms     86ms    0.16us    0.459ms
         SpecialClassAttribute:    228ms    234ms    0.19us    0.541ms
      SpecialInstanceAttribute:     88ms     90ms    0.08us    0.542ms
                StringMappings:    277ms    280ms    1.11us    0.434ms
              StringPredicates:     94ms     95ms    0.14us    1.868ms
                 StringSlicing:     94ms     96ms    0.17us    0.849ms
                     TryExcept:     58ms     59ms    0.03us    0.771ms
                    TryFinally:     64ms     66ms    0.41us    0.408ms
                TryRaiseExcept:     38ms     38ms    0.60us    0.408ms
                  TupleSlicing:     75ms     76ms    0.29us    0.043ms
                   WithFinally:     88ms     90ms    0.56us    0.408ms
               WithRaiseExcept:     97ms     99ms    1.24us    0.512ms
-------------------------------------------------------------------------------
Totals:                           4470ms   4545ms


The previous version that calculates linenumbers in each function call is about 9% slower that stock python. Sacrifying a bit of memory (O(2*n), with n is the size of bytecodes imported), the speed difference with stock python is 1.4%.

I think that paying 1.4% of performance hit is a good investment to enjoy DTrace probes in Python, being able to run an instrumentalized Python interpreter 100% of the time. In fact this instrumentalization can be used to locate hotspots in python interpreter and maybe improve overall performance.

Of course, platform with no dtrace or with dtrace support disabled when compiling python will no have any kind of performance hit.

Same calculations for 64 bit binaries:

***** STOCK PYTHON:

-------------------------------------------------------------------------------
PYBENCH 2.1
-------------------------------------------------------------------------------
* using CPython 3.3.0a0 (default:70ba352f9586, Dec 11 2011, 23:38:26) [GCC 4.6.2]
* disabled garbage collection
* system check interval set to maximum: 2147483647
* using timer: time.time

Calibrating tests. Please wait... done.

Running 10 round(s) of the suite at warp factor 10:

* Round 1 done in 3.392 seconds.
* Round 2 done in 3.423 seconds.
* Round 3 done in 3.397 seconds.
* Round 4 done in 3.425 seconds.
* Round 5 done in 3.395 seconds.
* Round 6 done in 3.465 seconds.
* Round 7 done in 3.476 seconds.
* Round 8 done in 3.388 seconds.
* Round 9 done in 3.385 seconds.
* Round 10 done in 3.388 seconds.

-------------------------------------------------------------------------------
Benchmark: 2011-12-11 23:39:33
-------------------------------------------------------------------------------

    Rounds: 10
    Warp:   10
    Timer:  time.time

    Machine Details:
       Platform ID:    SunOS-5.10-i86pc-i386-64bit-ELF
       Processor:      i386
    
    Python:
       Implementation: CPython
       Executable:     /home/python/cpython/python
       Version:        3.3.0a0
       Compiler:       GCC 4.6.2
       Bits:           64bit
       Build:          Dec 11 2011 23:38:26 (#default:70ba352f9586)
       Unicode:        UCS4


Test                             minimum  average  operation  overhead
-------------------------------------------------------------------------------
          BuiltinFunctionCalls:     58ms     61ms    0.12us    0.199ms
           BuiltinMethodLookup:     38ms     39ms    0.04us    0.233ms
                 CompareFloats:     44ms     51ms    0.04us    0.267ms
         CompareFloatsIntegers:    100ms    102ms    0.11us    0.199ms
               CompareIntegers:     68ms     78ms    0.04us    0.401ms
        CompareInternedStrings:     53ms     53ms    0.04us    1.015ms
                  CompareLongs:     38ms     45ms    0.04us    0.233ms
                CompareStrings:     45ms     46ms    0.05us    0.680ms
    ComplexPythonFunctionCalls:     57ms     58ms    0.29us    0.335ms
                 ConcatStrings:     52ms     53ms    0.11us    0.379ms
               CreateInstances:     88ms     89ms    0.80us    0.331ms
            CreateNewInstances:     66ms     68ms    0.80us    0.269ms
       CreateStringsWithConcat:     87ms     89ms    0.09us    0.672ms
                  DictCreation:     46ms     47ms    0.12us    0.279ms
             DictWithFloatKeys:     57ms     58ms    0.06us    0.503ms
           DictWithIntegerKeys:     47ms     48ms    0.04us    0.672ms
            DictWithStringKeys:     40ms     41ms    0.03us    0.672ms
                      ForLoops:     45ms     45ms    1.82us    0.031ms
                    IfThenElse:     54ms     55ms    0.04us    0.503ms
                   ListSlicing:     50ms     51ms    3.64us    0.042ms
                NestedForLoops:     65ms     67ms    0.04us    0.002ms
      NestedListComprehensions:     64ms     65ms    5.44us    0.066ms
          NormalClassAttribute:    129ms    130ms    0.11us    0.363ms
       NormalInstanceAttribute:     62ms     62ms    0.05us    0.365ms
           PythonFunctionCalls:     49ms     50ms    0.15us    0.203ms
             PythonMethodCalls:     69ms     69ms    0.31us    0.133ms
                     Recursion:     86ms     86ms    1.72us    0.334ms
                  SecondImport:     57ms     59ms    0.59us    0.131ms
           SecondPackageImport:     59ms     60ms    0.60us    0.131ms
         SecondSubmoduleImport:    103ms    104ms    1.04us    0.131ms
       SimpleComplexArithmetic:     45ms     45ms    0.05us    0.267ms
        SimpleDictManipulation:     84ms     84ms    0.07us    0.334ms
         SimpleFloatArithmetic:     46ms     47ms    0.04us    0.402ms
      SimpleIntFloatArithmetic:     57ms     58ms    0.04us    0.401ms
       SimpleIntegerArithmetic:     57ms     57ms    0.04us    0.401ms
      SimpleListComprehensions:     54ms     55ms    4.56us    0.066ms
        SimpleListManipulation:     42ms     43ms    0.04us    0.506ms
          SimpleLongArithmetic:     37ms     38ms    0.06us    0.199ms
                    SmallLists:     61ms     63ms    0.09us    0.266ms
                   SmallTuples:     63ms     65ms    0.12us    0.300ms
         SpecialClassAttribute:    184ms    187ms    0.16us    0.368ms
      SpecialInstanceAttribute:     62ms     63ms    0.05us    0.370ms
                StringMappings:    206ms    211ms    0.84us    0.293ms
              StringPredicates:     65ms     67ms    0.10us    1.328ms
                 StringSlicing:     74ms     75ms    0.13us    0.559ms
                     TryExcept:     36ms     36ms    0.02us    0.503ms
                    TryFinally:     45ms     45ms    0.28us    0.267ms
                TryRaiseExcept:     27ms     27ms    0.42us    0.267ms
                  TupleSlicing:     72ms     73ms    0.28us    0.030ms
                   WithFinally:     68ms     71ms    0.44us    0.267ms
               WithRaiseExcept:     73ms     76ms    0.94us    0.334ms
-------------------------------------------------------------------------------
Totals:                           3333ms   3413ms


********** DTRACE CALCULATING LINENUMBER IN EVERY FUNCTION CALL:

-------------------------------------------------------------------------------
PYBENCH 2.1
-------------------------------------------------------------------------------
* using CPython 3.3.0a0 (dtrace-issue13405:552edf5be75c, Dec 11 2011, 23:43:27) [GCC 4.6.2]
* disabled garbage collection
* system check interval set to maximum: 2147483647
* using timer: time.time

Calibrating tests. Please wait... done.

Running 10 round(s) of the suite at warp factor 10:

* Round 1 done in 3.898 seconds.
* Round 2 done in 3.849 seconds.
* Round 3 done in 3.857 seconds.
* Round 4 done in 3.887 seconds.
* Round 5 done in 3.833 seconds.
* Round 6 done in 3.837 seconds.
* Round 7 done in 3.842 seconds.
* Round 8 done in 3.853 seconds.
* Round 9 done in 3.870 seconds.
* Round 10 done in 3.840 seconds.

-------------------------------------------------------------------------------
Benchmark: 2011-12-11 23:44:53
-------------------------------------------------------------------------------

    Rounds: 10
    Warp:   10
    Timer:  time.time

    Machine Details:
       Platform ID:    SunOS-5.10-i86pc-i386-64bit-ELF
       Processor:      i386
    
    Python:
       Implementation: CPython
       Executable:     /home/python/cpython-jcea/python
       Version:        3.3.0a0
       Compiler:       GCC 4.6.2
       Bits:           64bit
       Build:          Dec 11 2011 23:43:27 (#dtrace-issue13405:552edf5be75c)
       Unicode:        UCS4


Test                             minimum  average  operation  overhead
-------------------------------------------------------------------------------
          BuiltinFunctionCalls:    107ms    109ms    0.21us    0.205ms
           BuiltinMethodLookup:     39ms     40ms    0.04us    0.239ms
                 CompareFloats:     44ms     45ms    0.04us    0.274ms
         CompareFloatsIntegers:     83ms     84ms    0.09us    0.204ms
               CompareIntegers:     70ms     70ms    0.04us    0.413ms
        CompareInternedStrings:     56ms     57ms    0.04us    1.053ms
                  CompareLongs:     40ms     41ms    0.04us    0.239ms
                CompareStrings:     49ms     51ms    0.05us    0.700ms
    ComplexPythonFunctionCalls:     74ms     77ms    0.39us    0.344ms
                 ConcatStrings:     54ms     54ms    0.11us    0.388ms
               CreateInstances:     97ms     98ms    0.88us    0.324ms
            CreateNewInstances:     73ms     74ms    0.88us    0.275ms
       CreateStringsWithConcat:     89ms     90ms    0.09us    0.692ms
                  DictCreation:     47ms     47ms    0.12us    0.274ms
             DictWithFloatKeys:     59ms     60ms    0.07us    0.519ms
           DictWithIntegerKeys:     48ms     49ms    0.04us    0.693ms
            DictWithStringKeys:     44ms     45ms    0.04us    0.693ms
                      ForLoops:     44ms     45ms    1.78us    0.031ms
                    IfThenElse:     59ms     59ms    0.04us    0.519ms
                   ListSlicing:     50ms     50ms    3.61us    0.040ms
                NestedForLoops:     68ms     69ms    0.05us    0.002ms
      NestedListComprehensions:     69ms     70ms    5.87us    0.068ms
          NormalClassAttribute:    130ms    134ms    0.11us    0.371ms
       NormalInstanceAttribute:     64ms     65ms    0.05us    0.373ms
           PythonFunctionCalls:     80ms     81ms    0.25us    0.201ms
             PythonMethodCalls:    102ms    103ms    0.46us    0.136ms
                     Recursion:    112ms    114ms    2.29us    0.343ms
                  SecondImport:     54ms     56ms    0.56us    0.135ms
           SecondPackageImport:     54ms     56ms    0.56us    0.135ms
         SecondSubmoduleImport:     99ms    101ms    1.01us    0.135ms
       SimpleComplexArithmetic:     48ms     49ms    0.06us    0.274ms
        SimpleDictManipulation:    137ms    139ms    0.12us    0.344ms
         SimpleFloatArithmetic:     45ms     45ms    0.03us    0.413ms
      SimpleIntFloatArithmetic:     57ms     59ms    0.04us    0.413ms
       SimpleIntegerArithmetic:     60ms     61ms    0.05us    0.413ms
      SimpleListComprehensions:     57ms     58ms    4.82us    0.067ms
        SimpleListManipulation:     76ms     77ms    0.07us    0.449ms
          SimpleLongArithmetic:     40ms     41ms    0.06us    0.204ms
                    SmallLists:     81ms     82ms    0.12us    0.274ms
                   SmallTuples:     71ms     72ms    0.13us    0.309ms
         SpecialClassAttribute:    188ms    191ms    0.16us    0.377ms
      SpecialInstanceAttribute:     63ms     64ms    0.05us    0.378ms
                StringMappings:    210ms    211ms    0.84us    0.296ms
              StringPredicates:    114ms    115ms    0.16us    1.408ms
                 StringSlicing:     77ms     78ms    0.14us    0.578ms
                     TryExcept:     48ms     48ms    0.02us    0.518ms
                    TryFinally:     93ms     99ms    0.62us    0.274ms
                TryRaiseExcept:     30ms     30ms    0.47us    0.274ms
                  TupleSlicing:     72ms     75ms    0.28us    0.030ms
                   WithFinally:     81ms     82ms    0.51us    0.274ms
               WithRaiseExcept:     82ms     84ms    1.05us    0.343ms
-------------------------------------------------------------------------------
Totals:                           3793ms   3857ms


********* SPENDING SOME MEMORY FOR PERFORMANCE:

-------------------------------------------------------------------------------
PYBENCH 2.1
-------------------------------------------------------------------------------
* using CPython 3.3.0a0 (dtrace-issue13405:43d1a819a63d, Dec 11 2011, 23:47:52) [GCC 4.6.2]
* disabled garbage collection
* system check interval set to maximum: 2147483647
* using timer: time.time

Calibrating tests. Please wait... done.

Running 10 round(s) of the suite at warp factor 10:

* Round 1 done in 3.529 seconds.
* Round 2 done in 3.579 seconds.
* Round 3 done in 3.526 seconds.
* Round 4 done in 3.517 seconds.
* Round 5 done in 3.538 seconds.
* Round 6 done in 3.547 seconds.
* Round 7 done in 3.526 seconds.
* Round 8 done in 3.518 seconds.
* Round 9 done in 3.512 seconds.
* Round 10 done in 3.550 seconds.

-------------------------------------------------------------------------------
Benchmark: 2011-12-11 23:49:03
-------------------------------------------------------------------------------

    Rounds: 10
    Warp:   10
    Timer:  time.time

    Machine Details:
       Platform ID:    SunOS-5.10-i86pc-i386-64bit-ELF
       Processor:      i386
    
    Python:
       Implementation: CPython
       Executable:     /home/python/cpython-jcea/python
       Version:        3.3.0a0
       Compiler:       GCC 4.6.2
       Bits:           64bit
       Build:          Dec 11 2011 23:47:52 (#dtrace-issue13405:43d1a819a63d)
       Unicode:        UCS4


Test                             minimum  average  operation  overhead
-------------------------------------------------------------------------------
          BuiltinFunctionCalls:     57ms     61ms    0.12us    0.203ms
           BuiltinMethodLookup:     40ms     41ms    0.04us    0.237ms
                 CompareFloats:     45ms     46ms    0.04us    0.272ms
         CompareFloatsIntegers:     85ms     85ms    0.09us    0.203ms
               CompareIntegers:     69ms     69ms    0.04us    0.410ms
        CompareInternedStrings:     65ms     65ms    0.04us    1.035ms
                  CompareLongs:     40ms     40ms    0.04us    0.237ms
                CompareStrings:     47ms     50ms    0.05us    0.694ms
    ComplexPythonFunctionCalls:     61ms     62ms    0.31us    0.341ms
                 ConcatStrings:     56ms     57ms    0.11us    0.385ms
               CreateInstances:     97ms     99ms    0.88us    0.329ms
            CreateNewInstances:     72ms     73ms    0.87us    0.275ms
       CreateStringsWithConcat:     87ms     88ms    0.09us    0.686ms
                  DictCreation:     46ms     47ms    0.12us    0.272ms
             DictWithFloatKeys:     59ms     60ms    0.07us    0.513ms
           DictWithIntegerKeys:     49ms     50ms    0.04us    0.686ms
            DictWithStringKeys:     43ms     43ms    0.04us    0.686ms
                      ForLoops:     43ms     44ms    1.77us    0.031ms
                    IfThenElse:     60ms     61ms    0.05us    0.513ms
                   ListSlicing:     50ms     51ms    3.65us    0.040ms
                NestedForLoops:     64ms     65ms    0.04us    0.002ms
      NestedListComprehensions:     66ms     67ms    5.57us    0.067ms
          NormalClassAttribute:    132ms    133ms    0.11us    0.370ms
       NormalInstanceAttribute:     64ms     65ms    0.05us    0.373ms
           PythonFunctionCalls:     62ms     62ms    0.19us    0.203ms
             PythonMethodCalls:     80ms     82ms    0.37us    0.135ms
                     Recursion:    105ms    106ms    2.12us    0.341ms
                  SecondImport:     53ms     54ms    0.54us    0.134ms
           SecondPackageImport:     53ms     54ms    0.54us    0.134ms
         SecondSubmoduleImport:     94ms     95ms    0.95us    0.134ms
       SimpleComplexArithmetic:     48ms     48ms    0.05us    0.272ms
        SimpleDictManipulation:     92ms     93ms    0.08us    0.337ms
         SimpleFloatArithmetic:     46ms     46ms    0.04us    0.411ms
      SimpleIntFloatArithmetic:     58ms     58ms    0.04us    0.409ms
       SimpleIntegerArithmetic:     57ms     58ms    0.04us    0.409ms
      SimpleListComprehensions:     55ms     57ms    4.79us    0.067ms
        SimpleListManipulation:     45ms     46ms    0.04us    0.422ms
          SimpleLongArithmetic:     38ms     39ms    0.06us    0.203ms
                    SmallLists:     62ms     64ms    0.09us    0.272ms
                   SmallTuples:     66ms     67ms    0.12us    0.306ms
         SpecialClassAttribute:    187ms    191ms    0.16us    0.374ms
      SpecialInstanceAttribute:     64ms     65ms    0.05us    0.378ms
                StringMappings:    198ms    199ms    0.79us    0.295ms
              StringPredicates:     68ms     69ms    0.10us    1.380ms
                 StringSlicing:     75ms     76ms    0.14us    0.570ms
                     TryExcept:     46ms     46ms    0.02us    0.513ms
                    TryFinally:     54ms     54ms    0.34us    0.272ms
                TryRaiseExcept:     27ms     27ms    0.43us    0.272ms
                  TupleSlicing:     74ms     75ms    0.29us    0.031ms
                   WithFinally:     82ms     84ms    0.53us    0.272ms
               WithRaiseExcept:     91ms     93ms    1.17us    0.341ms
-------------------------------------------------------------------------------
Totals:                           3477ms   3534ms


Here the performance penalty is 13% for the version that calculates linenumbers in each function call, and 3.5% for the memory spending extra memory for performance. The extra performance hit is because, possibly, the extra C function call and C stack massaging. Something to think about.

Very high-level comments on your patch:

- why an empty "dtrace" module?

- I'm worried that you're adding lots of delicate code inside critical core functions. Perhaps most of it can be factored out in separate functions living in another (dtrace-specific) C file? I don't think we really want to maintain some asm("nop") in the GC module, and I'm not even talking about the madness in ceval.c.

- instead of generating code data (line numbers etc.) up front, why not generate and cache it lazily? that way, it would only be generated when the probes are really used (IIUC)

For higher-level benchmarks, I suggest you take a look at http://hg.python.org/benchmarks/

> Alan, I would open a new issue tracking this one and posting a patch there, if I were you.
>
> Previous DTRACE attempts failed because trying to make everybody happy. I don't want to repeat the mistake.
>

Sorry, but I'm -1.
I don't feel comfortable with adding a such amount of intrusive code,
which will have to be maintained as the interpreter evolves, to add
probes just for Solaris derivatives, which is, with all due respect,
really a niche platform. So If we merge this, this should at least
support SystemTap upfront.

> In fact this instrumentalization can be used to locate hotspots in python interpreter and maybe improve overall performance.

You can already go a really long way with just strace and oprofile, I
don't really but the performance optimization argument.

Also, I must admit I'm quite skeptical about the real benefit of
explicit probes for user-land, especially for CPython which isn't used
for performance-critical systems...

2011/12/12 Charles-François Natali <report@bugs.python.org>

>
> Charles-François Natali <neologix@free.fr> added the comment:
>
> > Alan, I would open a new issue tracking this one and posting a patch
> there, if I were you.
> >
> > Previous DTRACE attempts failed because trying to make everybody happy.
> I don't want to repeat the mistake.
> >
>
> Sorry, but I'm -1.
> I don't feel comfortable with adding a such amount of intrusive code,
> which will have to be maintained as the interpreter evolves, to add
> probes just for Solaris derivatives, which is, with all due respect,
> really a niche platform. So If we merge this, this should at least
> support SystemTap upfront.
>

Is SystemTap an alternative to DTrace? I see that SystemTap is only for
Linux, while DTrace is available also on MacOS and FreeBSD.

According to Stan Cox, this patch "almost" work with SystemTap. Moreover, there are work porting DTrace to Linux.

DTrace helping to improve performance is secondary. The real important thing is the "observability". It is difficult to understand the advantages without experimenting directly, but possibilities are endless.

Just an example:

Yesterday I was kind of worried about the memory cost in the last version. I know that the extra memory used is around 2*n, where "n" is the bytecode size. But what is that in a real world cost?.

I wrote the following dtrace script:

"""
unsigned long int tam;
unsigned int num;

pid$target::PyCode_New:entry
{
    self->flag=1;
}

pid$target::PyCode_New:return
{
    self->flag=0;
}

pid$target::PyMem_Malloc:entry
/self->flag/
{
    self->tam=arg0;
    tam+=arg0;
    num+=1;
    printf(\"%d %d\", num, tam);
}

pid$target::PyMem_Malloc:return
/self->flag/
{
    pos[arg1]=self->tam;
    self->tam=0;
}

pid$target::PyMem_Free:entry
/pos[arg0]/
{
    num-=1;
    tam-=pos[arg0];
    pos[arg0]=0;
}
"""

This code bookkeeps details about the extra allocations/deallocations at import/reload() time.

Note that this code DOESN'T use the new Python probes. You could use them, for instance, to know which module/function is doing the lion share of imports.

You launch this code with "dtrace -s SCRIPT.d -c COMMAND".

Some real world examples:

- Interactive interpreter invocation: 517 blocks, 95128 bytes.

- BitTorrent tracker with persistence (DURUS+BerkeleyDB) backend: 2122 blocks, 439332 bytes.

- Fully functional LMTP+POP3 server written in Python, with persistence (DURUS+BerkeleyDB) backend: 2182 blocks, 422288 bytes.

- RSS to Twitter gateway, with OAuth: 2680 blocks, 556636 bytes. Surprising the import weight that brings "feedparser" and "bitly" libraries.

So the memory hit seems pretty reasonable. And I can verify it without ANY change in Python.

In this case I am launching python "inside" dtrace because I want to see the complete picture, from the very beginning. But usually you "plug" a long running python process for a while, without stopping it at all, and when you are done, you shutdown the tracing script... without ANY disturbance of the running python program, that keeps working. For instance, your server code is being slow for some reason *NOW*. You use DTrace to study what the program is doing just NOW. You don't have to stop the program, add "debug" code to it an launch again and WAIT until the problem happens again, determine that your "debug" code is not helping, changing it, repeat...

This is observability. Difficult to explain. Life sucks when you are used to it and you don't have it.

> - Interactive interpreter invocation: 517 blocks, 95128 bytes.

Note that http://bugs.python.org/issue13390 also proposes to count
allocations in the interpreter.

> - why an empty "dtrace" module?

This is preliminary. I am thinking about dynamic probes, something like "logging" module but using dtrace. Still experimenting, not sure is actually possible.

Martin V Löwis suggested to use "sys.flags".

Undecided yet.

> - I'm worried that you're adding lots of delicate code inside
> critical core functions. Perhaps most of it can be factored out in
> separate functions living in another (dtrace-specific) C file? I
> don't think we really want to maintain some asm("nop") in the GC
> module, and I'm not even talking about the madness in ceval.c.

ceval.c madness is greatly reduced in the last version. I was not happy with it either. I am open to suggestions...

The point of DTrace probes is its very low overhead. If I change macros to external function calls, your performance will be suffer.

That said, I am open to suggestions, more understandable code, etc.

> - instead of generating code data (line numbers etc.) up front, why
> not generate and cache it lazily? that way, it would only be
> generated when the probes are really used (IIUC)

This case is special. This data is used by the kernel, when a DTrace script does a "jstack()". At this moment you can not CALL anything. You don't even have loops or "if".

Example: your program seems hangup, aparently. You can write a single line DTrace script to dump the jstack and see what your program is doing, even if it stuck in, let say, a function call. At this moment you can't call ANYTHING. So I precalculate the line offsets at import time, and use the table here. There is little else I can do, in kernel context.

> For higher-level benchmarks, I suggest you take a look at
> http://hg.python.org/benchmarks/

Good suggestions. I will check it.

>> - Interactive interpreter invocation: 517 blocks, 95128 bytes.
>
> Note that http://bugs.python.org/issue13390 also proposes to count
> allocations in the interpreter.

The thing is, I get this data WITHOUT touching python interpreter, using a DTrace script, and when I am done and I kill the script, any malloc/free overhead will disappear. And the program keeps running...

Notice too, that the data I am showing is the extra memory I am using for the dtrace stack helper, not all python memory (if you check the dtrace script, I only contabilize "PyMem_Malloc()" when called from "PyCode_New()").

DTrace allows me to be quirurgic.

> Notice too, that the data I am showing is the extra memory I am using
> for the dtrace stack helper, not all python memory (if you check the
> dtrace script, I only contabilize "PyMem_Malloc()" when called from
> "PyCode_New()").
> 
> DTrace allows me to be quirurgic.

I am not disputing the flexibility of dtrace. However, it is also
platform-specific, and needs you to learn a dedicated programming
language and API.

On Mon, Dec 12, 2011 at 6:26 PM, Antoine Pitrou <report@bugs.python.org>wrote:

>
> I am not disputing the flexibility of dtrace. However, it is also
> platform-specific, and needs you to learn a dedicated programming
> language and API.

If it is flexible, then I won't see any problems to create a pythonic
interface for it.  If you want to inspect Python in real-time from itself -
that's I believe is another story.

systemtap doesn't have have a ustack helper, but if the frame pointer were provided to PYTHON_FUNCTION_ENTRY, then it could be cached to provide python stack frame access.

--- Python/ceval.c.1	2011-12-07 11:18:03.733659382 -0500
+++ Python/ceval.c	2011-12-19 18:45:54.601309213 -0500
@@ -796,3 +796,3 @@
 	lineno = PyCode_Addr2Line(f->f_code, f->f_lasti);
-	PYTHON_FUNCTION_ENTRY(filename, name, lineno);
+	PYTHON_FUNCTION_ENTRY(filename, name, lineno, f);

As I said, I'm skeptical about the benefit vs maintenance burden ratio, especially since cPython doesn't target performance critical applications. I just fear that's a lot of intrusive code which will only be used by a handful of people worldwild, but I could be wrong.
But I'm definitely not stubborn, so if other core developers think it's a worthwhile feature, I won't object to it (but I'd really prefer if the patch also supported SystemTap).

Code ready for commit.

Please, review.

After the first commit, I will try to make it compatible with MacOS and FreeBSD. Current target is Solaris and derivatives (OpenIndiana, for instance)

Stan Cox, if you want systemtap compatibility at this moment, please provide a patch. The first patch doesn't need "ustack" compatibility. In fact, MacOS dtrace, for instance, seems not to have "ustack" support at all (according to Google), so the feature is very convenient but optional.

I'm -1 on this patch for essentially the same reasons as Charles-François. It introduces a lot of code (and hacks!) in critical pathways of the interpreter. Someone would have to be constantly maintaining and testing it. In return, what do we get?

NOTE to myself: In OpenIndiana we could have this error:

"""
dtrace: failed to compile script ./Include/phelper.d: Preprocessor not found
"""

In that case, we must install the C preprocessor:

"""
pfexec pkg install cpp
"""

I confirm that current 3.3 patch works in the 32 bits OpenIndiana Python buildbots, after adding this patch (already available in my mercurial repository, but not in the patch published in this issue):

"""
diff --git a/Lib/test/test_dtrace.py b/Lib/test/test_dtrace.py
--- a/Lib/test/test_dtrace.py
+++ b/Lib/test/test_dtrace.py
@@ -173,7 +173,7 @@
         # Verify that we are checking:
         opcodes = set(["CALL_FUNCTION", "CALL_FUNCTION_VAR",
             "CALL_FUNCTION_KW", "CALL_FUNCTION_VAR_KW"])
-        obj = compile(open(sample).read(), "sample", "exec")
+        obj = compile(open(sample, encoding="utf-8").read(), "sample", "exec")
         class dump() :
             def __init__(self) :
                 self.buf = []
"""

Also, of course, the user must have dtrace permissions, as documented in a previous message.

Charles-François:
> Also, I must admit I'm quite skeptical about the real benefit of
explicit probes for user-land, especially for CPython which isn't used
for performance-critical systems...

I beg to differ.  CPython is totally used on performance-critical systems, and I know I'm not the only user who thinks that.  "Performance-critical" doesn't necessarily mean "goes as fast as it ever possibly can", clearly PyPy is the place to go for that, but "can process at least X work in Y time".  Meeting performance goals with CPython is already challenging enough, please don't make it artificially hard by refusing to integrate tools which help users understand and improve performance.

Benjamin:
> I'm -1 on this patch for essentially the same reasons as Charles-François. It introduces a lot of code (and hacks!) in critical pathways of the interpreter. Someone would have to be constantly maintaining and testing it. In return, what do we get?

You get support for a highly sophisticated and low-impact profiling and tracing technology which provides support for illuminating performance problems *as well as* complicated behavioral problems that only happen under load, without slowing down the interpreter as a whole.  Not to mention possible integration with a whole slew of tools that know how to deal with data from that system.

I'm not saying that this is necessarily worth the maintenance burden; your analysis of the tradeoff may ultimately be correct.  I can't presume to know that because I am not intimately familiar with all the code it touches.  But it's definitely not nothing.

I would strongly suggest those of you who are not "getting it" to actually try Jesus's patch out in some real scenarios. You'll quickly see what the benefit is. I think some of you are missing that it's a *not* just about performance: it's a system comprehension tool. It's there to help answer questions, on a live system; sometimes those are performance questions, but more often they're *not*.

I can't speak as to the maintenance burden. I'm sure we can all agree that the  ceval.c changes are not pretty - it's why I never submitted my original changes. But speaking for the Solaris organization, the burden of maintaining our patches across the various Python releases has been minimal.

As great as a tool it maybe, it's still only available on a minority platform. So I couldn't really try it.

On Fri, 2012-01-20 at 04:46 +0000, Benjamin Peterson wrote:
> Benjamin Peterson <benjamin@python.org> added the comment:
> 
> As great as a tool it maybe, it's still only available on a minority platform. So I couldn't really try it.

FWIW, the analogous systemtap patch works great on Linux, or, at least
Fedora 13+/RHEL 6 (though beware: not all Linux distributions have
systemtap working properly out of the box, alas).

See:
http://fedoraproject.org/wiki/Features/SystemtapStaticProbes#Python_2
and http://bugs.python.org/issue4111 though this stalled due to lack of
documentation (I started writing some, but got bogged down in the
differences between the tapsets and the static markers; sorry).

Dave

I am an almost complete 0 in C system programming and in DTrace matters,
but I feel like DTrace has a potential to help me understand internal
CPython processes better. If maintenance of the code with DTrace is hard,
there are several ways to make it easier:

1. PyCon talk and a reference to video (why DTrace is cool for Python and
how to use it)
2. Chapter in Development guide explaining DTrace magic, how it works
3. Annotated example (like in "dive into" series)

My point about DTrace probes is not performance per-se but observability.

An OS with DTrace support can be completely inspected and shows you ALL the inner working. You can see a particular pattern in the operating system and locate the syscalls and the process involved. If it is a compiled program, you can actually look inside it and locate the particular function responsible and, even, its arguments.

You can not do that easily with an interpreted program, because when you inspect the stacktrace, you see the C interpreter functions, not the actual interpreted functions running. So, to be appropriately integrated with the impressive observability of the entire system, the interpreter must cooperate. That is the role of this patch. And that role is crucial.

Just an example I was checking today, just for fun: an email server written in Python.

I am interested in knowing which function is involved in database "misses", and so real READ harddisk activity. Since Berkeley DB is used as the backend, and Oracle has included dtrace probes on the library (http://docs.oracle.com/cd/E17076_02/html/programmer_reference/program_perfmon.html), we can do something like this:

"""
dtrace -n "bdb1066:::mpool-miss {@misses[jstack(20)]=count();}"
"""

This on-liner will trace process "1066" and with plug into the Berkeley DB cache miss event, recording the python stack (up to 20 levels) at each event fire. We let the monitor script go for a few seconds and ^c it, showing something like:

"""
dtrace: description 'bdb1066:::mpool-miss ' matched 1 probe
^C


              libdb-5.3.so`__memp_fget+0x22cb
              libdb-5.3.so`__ham_get_cpage+0x140
              libdb-5.3.so`__ham_lookup+0x8b
              libdb-5.3.so`__hamc_get+0x3d5
              libdb-5.3.so`__dbc_iget+0x40d
              libdb-5.3.so`__dbc_get+0x9d
              libdb-5.3.so`__db_get+0xb8
              libdb-5.3.so`__db_get_pp+0x2db
              _pybsddb.so`DB_get+0x1f5
              libpython2.7.so.1.0`PyCFunction_Call+0x148
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x55f2
                [ /export/home/correo/durus-berkeleydbstorage/berkeleydb_storage.py:317 (_prefetch_thread) ]
              libpython2.7.so.1.0`PyEval_EvalCodeEx+0x7a4
              libpython2.7.so.1.0`function_call+0x18f
              libpython2.7.so.1.0`PyObject_Call+0x5c
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x1d8e
                [ /usr/local/lib/python2.7/threading.py:505 (run) ]
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x63ed
                [ /usr/local/lib/python2.7/threading.py:552 (__bootstrap_inner) ]
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x63ed
                [ /usr/local/lib/python2.7/threading.py:525 (__bootstrap) ]
              libpython2.7.so.1.0`PyEval_EvalCodeEx+0x7a4
              libpython2.7.so.1.0`function_call+0x9a
              libpython2.7.so.1.0`PyObject_Call+0x5c
                1

              libdb-5.3.so`__memp_fget+0x22cb
              libdb-5.3.so`__ham_get_cpage+0x140
              libdb-5.3.so`__ham_lookup+0x8b
              libdb-5.3.so`__hamc_get+0x3d5
              libdb-5.3.so`__dbc_iget+0x40d
              libdb-5.3.so`__dbc_get+0x9d
              libdb-5.3.so`__db_get+0xb8
              libdb-5.3.so`__db_get_pp+0x2db
              _pybsddb.so`DB_get+0x1f5
              libpython2.7.so.1.0`PyCFunction_Call+0x148
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x55f2
                [ /export/home/correo/durus-berkeleydbstorage/berkeleydb_storage.py:725 (load) ]
              libpython2.7.so.1.0`PyEval_EvalCodeEx+0x7a4
              libpython2.7.so.1.0`function_call+0x18f
              libpython2.7.so.1.0`PyObject_Call+0x5c
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x1d8e
                [ /export/home/correo/durus-berkeleydbstorage/berkeleydb_storage.py:430 (f) ]
              libpython2.7.so.1.0`PyEval_EvalCodeEx+0x7a4
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x4f89
                [ build/bdist.solaris-2.10-i86pc/egg/durus/storage_server.py:302 (_send_load_response) ]
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x63ed
                [ build/bdist.solaris-2.10-i86pc/egg/durus/storage_server.py:295 (handle_L) ]
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x63ed
                [ build/bdist.solaris-2.10-i86pc/egg/durus/storage_server.py:261 (handle) ]
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x63ed
                [ build/bdist.solaris-2.10-i86pc/egg/durus/storage_server.py:227 (serve) ]
                2

              libdb-5.3.so`__memp_fget+0x22cb
              libdb-5.3.so`__ham_get_cpage+0x140
              libdb-5.3.so`__ham_lookup+0x8b
              libdb-5.3.so`__hamc_get+0x3d5
              libdb-5.3.so`__dbc_iget+0x40d
              libdb-5.3.so`__dbc_get+0x9d
              libdb-5.3.so`__db_get+0xb8
              libdb-5.3.so`__db_get_pp+0x2db
              _pybsddb.so`DB_get+0x1f5
              libpython2.7.so.1.0`PyCFunction_Call+0x148
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x55f2
                [ /export/home/correo/durus-berkeleydbstorage/berkeleydb_storage.py:307 (_prefetch_thread) ]
              libpython2.7.so.1.0`PyEval_EvalCodeEx+0x7a4
              libpython2.7.so.1.0`function_call+0x18f
              libpython2.7.so.1.0`PyObject_Call+0x5c
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x1d8e
                [ /usr/local/lib/python2.7/threading.py:505 (run) ]
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x63ed
                [ /usr/local/lib/python2.7/threading.py:552 (__bootstrap_inner) ]
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x63ed
                [ /usr/local/lib/python2.7/threading.py:525 (__bootstrap) ]
              libpython2.7.so.1.0`PyEval_EvalCodeEx+0x7a4
              libpython2.7.so.1.0`function_call+0x9a
              libpython2.7.so.1.0`PyObject_Call+0x5c
               25

              libdb-5.3.so`__memp_fget+0x22cb
              libdb-5.3.so`__ham_get_cpage+0x140
              libdb-5.3.so`__ham_lookup+0x8b
              libdb-5.3.so`__hamc_get+0x3d5
              libdb-5.3.so`__dbc_iget+0x40d
              libdb-5.3.so`__dbc_get+0x9d
              libdb-5.3.so`__db_get+0xb8
              libdb-5.3.so`__db_get_pp+0x2db
              _pybsddb.so`DB_get+0x1f5
              libpython2.7.so.1.0`PyCFunction_Call+0x148
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x53ee
                [ /export/home/correo/durus-berkeleydbstorage/berkeleydb_storage.py:758 (end) ]
              libpython2.7.so.1.0`PyEval_EvalCodeEx+0x7a4
              libpython2.7.so.1.0`function_call+0x18f
              libpython2.7.so.1.0`PyObject_Call+0x5c
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x1d8e
                [ /export/home/correo/durus-berkeleydbstorage/berkeleydb_storage.py:444 (f) ]
              libpython2.7.so.1.0`PyEval_EvalCodeEx+0x7a4
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x4f89
                [ build/bdist.solaris-2.10-i86pc/egg/durus/storage_server.py:354 (handle_C) ]
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x63ed
                [ build/bdist.solaris-2.10-i86pc/egg/durus/storage_server.py:261 (handle) ]
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x63ed
                [ build/bdist.solaris-2.10-i86pc/egg/durus/storage_server.py:227 (serve) ]
              libpython2.7.so.1.0`PyEval_EvalFrameEx+0x63ed
                [ /export/home/correo/lmtp.py:1206 (storage_background) ]
               72
"""

We can see which function (even which thread) is causing the database miss. The number after each frame shows how many times we saw that particular stacktrace.

Let's suppose now I am interested in knowing how long SMTP transactions are. Let's do something like this:

"""
python$target:::function-entry
/copyinstr(arg1)=="lmtp2"/
{
  self->ts = timestamp;
}

python$target:::function-return
/(copyinstr(arg1)=="lmtp2") && (self->ts)/
{
  @time_lmtp = quantize(timestamp-self->ts);
  self->ts = 0;
}

"""

And the result after a few seconds: (time in nanoseconds)

"""
           value  ------------- Distribution ------------- count    
         8388608 |                                         0        
        16777216 |@@@@@@@@@@@@@@@@@                        8        
        33554432 |@@@@@@@@@@@@@@@@@@@@@@@                  11       
        67108864 |                                         0 
"""

(The values are pessimistic, because the activated probes have performance hit).

You can do things like monitor garbage collection events, count object allocation/deallocation to find memory leaks, relate network activity with disk activity, whatever you can imagine. And not only inside the program, but connect any activity in the system with the root cause.

Another example. In this particular program the database runs in a separate thread inside the same process, connected to the other threads via a socket. Sometimes the socket can timeout if the database is being slow. In that case, the thread with the timeout will close the connection to the database and will open a new connection, redoing the transaction (the system is ACID, so we can do this). How often is that happening?. No idea. I could change python code to log reconnections or I could run an one-liner dtrace script on my server hooking to the reconnection routine to get an inmediate feedback of how frequent is this event firing.

Note that during all this detailed monitoring, the email server keeps working. We don't stop it. We don't change a single line of production code. Any effect the probes could have (performance, for instance) will vanish as soon as the monitoring script is stopped.

And yes, you can do this, frequently, stopping the process and instrumentalizing it by hand. But that disturb the service, it is error prone and there are things you simply can't do because your are instrumentalizing your code, not the C libraries neither the entire operating system. For instance, you can't easily correlate events between two different processes. With DTrace, you can. 

Moreover, this kind of investigation is iterative. You make an hypothesis, write an small script to validate, run it and collect some data, and write another script to explore what you found. If you do that modifying the original sourcecode, you must patch and restart the process constantly. And your patch could crash the server, for instance.

DTrace is very useful too when a process has sporadic problems and you can't just stop it because the problem goes away if you do, and you can't easily find the reason.

So, yes, usually you are interested in performance, but that is a consequence of "visibility" into your program and the entire system. The real deal is the "observability".

About DTrace being a niche, current code works in Solaris and derivatives. It is a quite popular OS in servers. Beside, I plan to support FreeBSD and MacOS too. I think this could be easy (although MacOS lacks the stack dump feature, shame on you, Apple :). Moreover, there are interest in using this with Linux systemtap capabilities, via the stap/DTrace compatibility layer. That seems to be doable too.

You could say "OK, come back when you have ALL that support". Previous attempts failed because of this, to try to cover ALL bases. I am quite sure that if we commit current code and enable it in the current Solaris & OpenIndiana buildbots, other people is going to "kill" :-) to get support in FreeBSD and MacOS too, and Fedora folks -for instance- sure would provide systemtap.

About the maintenance burden, I am a core developer and quite committed to Solaris&family technology. I plan to be around for quite a while, actually. But this technology can be deleted COMPLETELY from current code simply deleting the conditional compilation (there is no 'convenient' code that is not conditionally compiled). You could drop the support anytime, since it would affect no python program at all. Python programs don't know anything about dtracing. DTrace is used by external tools.

There is a point about "let's keep this patch as an external patch that interested parties can apply by themselves". Beside considering that this work deserves to be in mainline python, a "patch" doesn't have buildbot testing and most users are stuck with whatever precompiled python their distributions choose to adopt. Even if linux distributions are interested, an external patch doesn't have the same credibility.

I have the python2.7 patch in production in my servers for the last month or so. 99.99% of the time I don't use it, and the performance hit I am paying for having this patch compiled in (it is completely optional via "configure") is about 1.4%. The other 0.01% of the time I really need it. REALLY. So badly that even decide what operating system I am using, or push me to work hard to create a patch useful to others.

So, yes. The code is intrusive. The code deals with a lot of internal machinery (PEP393 support in the ustack helper was quite difficult). It is going to break from time to time, sure. At the same time, I am committed to support it. And even if it is dropped in 3.4, no Python program will be affected.

Last but not least, other interpreted languages already have DTrace support:

* PHP:

 - http://techportal.ibuildings.com/2009/11/24/analysing-php-web-applications-with-dtrace/
 - https://wiki.php.net/rfc/dtrace

* PERL:

 - https://dgl.cx/2011/01/dtrace-and-perl

* RUBY:

 - http://ruby-dtrace.rubyforge.org/

 - https://rubygems.org/gems/ruby-dtrace

* HASKELL:

 - http://hackage.haskell.org/trac/ghc/wiki/DTrace

 - http://justtesting.org/profiling-garbage-collection-in-haskell-with

* JAVA:

 - http://docs.oracle.com/javase/6/docs/technotes/guides/vm/dtrace.html

* JAVASCRIPT:

 - https://wiki.mozilla.org/Performance/Optimizing_JavaScript_with_DTrace

Googling around you can see dtrace probes everywhere, from languages to libraries to, even, the X-Server: http://www.x.org/releases/X11R7.6/doc/xorg-server/Xserver-DTrace.html

> So, yes. The code is intrusive. The code deals with a lot of internal
> machinery (PEP393 support in the ustack helper was quite difficult).
> It is going to break from time to time, sure. At the same time, I am
> committed to support it. And even if it is dropped in 3.4, no Python
> program will be affected.

To ease the concerns, I think you should make it so that dtrace-specific
code gets out of the way as much as possible.
I suggest you create a Python/ceval-dtrace.h header and put most
dtrace-specific code from ceval.c there. Its inclusion should be
conditional on WITH_DTRACE so that other core devs can ignore its
presence.

A couple other comments:
- in the makefile, DTRACEOBJS is inconsistent with DTRACE_STATIC and
LIBRARY_OBJS. You should make it DTRACE_OBJS.
- please add comments at the top of whatever header files you add, to
make it clear that they are dtrace-specific. Mentions of "ustack helper"
are a bit too specific to be helpful.
- some code lacks error checking, e.g. when calling PyUnicode_AsUTF8.
- is co_linenos ever freed or is it a memory leak?
- your indices and offsets should be Py_ssize_t, not int
- is an empty dtrace module really needed? a flag variable in the sys
module should be enough
- as you can see the Makefile uses "-rm -f", you should probably do the
same instead of "rm -f"
- you have a rather strange "if true" in your configure.in additions

Thanks in advance.

This is a subset of the dtrace patch and consists of the minimal functionality
needed by systemtap.  The only files that are changed from upstream sources are
as follows.

* configure/configure.in
* Makefile.pre.in
* pyconfig.h.in
  Same changes as the dtrace patch except there is no phelper.

* pydtrace.d
  Same change as the dtrace patch except added PyFrameObject to probes.
  Instead of passing in fields like filename and function name, the systemtap
  scripts (not shown) use PyFrameObject and access the python data structures.
  The overhead for a systemtap probe is a single nop and PyFrameObject is
  possibly live at the probe point so the overhead will be minimal.  pydtrace.h
  is always generated since this file is different for dtrace and stap.

* ceval.c
  The only changes to ceval.c from the upstream version are the addition of the
  PYTHON_FUNCTION_ENTRY and PYTHON_FUNCTION_RETURN probes.
  PYTHON_FUNCTION_ENTRY is invoked directly since the overhead of the probe is
  less than the overhead of a conditional check.  The probe passes the
  PyFrameObject, as mentioned above, but nothing else.  Likewise for
  PYTHON_FUNCTION_RETURN.

systemtap tapset, not included in patch, will provide backtrace results such as:
 #0 main  at /.../python/celsius.py:19
 #1 <module>  at /.../python/celsius.py:3
 #2 celsius_to_farenheit (celsius:int ) at /.../python/celsius.py:7
and variable trace results such as:
 tuple atuple in celsius_to_farenheit at /.../python/celsius.py =  "a", "b", "c",
 list alist in celsius_to_farenheit at /.../python/celsius.py = [ 1, 2, 3,]
 set aset in celsius_to_farenheit at /.../python/celsius.py = { 1, 2, 3,}
...

jcea: BTW, will you be at PyCon US this year?  if so, can we sprint on getting the DTrace and SystemTap hooks into CPython in some form acceptable to the rest of the CPython maintainers?

Dave, I am in Europe (Spain), and I can't afford (money and time) to go to PyCon. If you are going and are interested in pushing this, we can talk about our respectives ideas and plans, to present a consensus plan.

Jesús said he was focusing on Solaris and couldn't help with OS X. Not sure if anyone else was going to try tackling that...

Just tried the patch `issue13405_4027.diff` on OS X 10.6.8.

First problem I ran into was:

gcc -fno-strict-aliasing -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes    -I. -I./Include    -DPy_BUILD_CORE -o ./Include/phelper_offsets \
		./Include/phelper_offsets.c
./Include/phelper_offsets.c: In function 'main':
./Include/phelper_offsets.c:23: warning: format '%d' expects type 'int', but argument 2 has type 'long int'
./Include/phelper_offsets.c:26: warning: format '%d' expects type 'int', but argument 2 has type 'long unsigned int'
./Include/phelper_offsets.c:28: warning: implicit declaration of function 'offsetof'
./Include/phelper_offsets.c:28: error: expected expression before 'PyCompactUnicodeObject'
./Include/phelper_offsets.c:30: error: expected expression before 'PyCompactUnicodeObject'
make: *** [Include/phelper_offsets.h] Error 1

OS X seems to have `offsetof` defined in `stddef.h` -- adding `#include <stddef.h>` got this to compile.

The next problem was with: 

```
if test "dtrace" != "" ; then \
		dtrace -o Python/phelper.o -DPHELPER -64 \
			-I. -I./Include   -C -G -s ./Include/phelper.d ; \
	else	touch Python/phelper.o ; \
	fi;
```

This fails because DTrace on OS X doesn't have the -G option. Removing the `-G` (total hack since it seems like `-G` is not at all a trivial option) results in:

```
dtrace: failed to initialize dtrace: DTrace requires additional privileges
```

Adding `sudo` isn't a practical solution, but I tried it to see if it would help or if there would be other errors and there was another error:

```
dtrace: ignored option -- 64
/dev/fd/5:42:8: warning: undefining "__STDC__"
dtrace: failed to compile script ./Include/phelper.d: "/usr/include/libkern/_OSByteOrder.h", line 98: specified storage class not appropriate in D
make: *** [Python/phelper.o] Error 1
```

With an hg checkout, I don't run into the `offsetof` problem - it fails when it gets to calling dtrace to generate Python/dtrace.o (again -G is the culprit).

```
$ hg clone https://hg.jcea.es/cpython-2011/
$ cd cpython-2011
$ hg update dtrace-issue13405_2.7
$ ./configure --prefix=/Users/marca/custom --enable-shared --with-dtrace
...
$ make
...
$ make
if test "dtrace" != "" ; then \
		dtrace -o Python/dtrace.o -64 \
			-C -G -s ./Include/pydtrace.d \
				Python/ceval.o Modules/gcmodule.o \
				Objects/classobject.o Objects/typeobject.o; \
	else    touch Python/dtrace.o ; \
	fi;
dtrace: ignored option -- 64
Usage: dtrace [-aACeFHlqSvVwZ] [-arch i386|x86_64] [-b bufsz] [-c cmd] [-D name[=def]]
	[-I path] [-L path] [-o output] [-p pid] [-s script] [-U name]
	[-x opt[=val]]
...
```

My understanding of DTrace is extremely shallow, but I think there is a major difference in how USDT probes are created between Solaris and OS X. Whereas on Solaris one generates object code using the -G option of dtrace and then links it in with the application, it seems that on OS X, the header file that dtrace -h spits out already has the magic assembler voodoo in it and thus you don't link with anything extra for DTrace. If that's true, then we probably need Makefile ifdef stuff to make it work.

If someone can verify my theories, I might be inclined to take a stab at it.

I noticed that jcea already had some commented out stuff for OS X in his configure.in.

I tried it out and stuff builds and works in a basic way, although it might not be fully functional.

```
~/src/python-hg/cpython-2011$ hg diff configure.in
diff -r b50130b35288 configure.in
--- a/configure.in	Wed Feb 22 02:15:47 2012 +0100
+++ b/configure.in	Wed Feb 22 14:19:42 2012 -0800
@@ -2670,8 +2670,7 @@
         DFLAGS="-32"
     fi
 
-    #if dtrace -G -o /dev/null Include/pydtrace.d 2>/dev/null
-    if true
+    if dtrace -G -o /dev/null Include/pydtrace.d 2>/dev/null
     then
         DTRACE_NM=SOLARIS
         AC_DEFINE(WITH_DTRACE, 1,
```

```
~/src/python-hg/cpython-2011$ ./configure --prefix=/Users/marca/custom --enable-shared --with-dtrace
...
~/src/python-hg/cpython-2011$ make
...
~/src/python-hg/cpython-2011$ DYLD_LIBRARY_PATH=. python2.7
Python 2.7.2+ (dtrace-issue13405_2.7:b50130b35288+, Feb 22 2012, 14:11:17) 
[GCC 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.1.00)] on darwin
Type "help", "copyright", "credits" or "license" for more information.
>>> import os
>>> os.getpid()
34764

# In another tab...
$ sudo dtrace -l | grep python34764
124748 python34764 libpython2.7.dylib            PyEval_EvalFrameExReal function-entry
124749 python34764 libpython2.7.dylib            PyEval_EvalFrameExReal function-return
124750 python34764 libpython2.7.dylib                           collect gc-done
124751 python34764 libpython2.7.dylib                           collect gc-start
124752 python34764 libpython2.7.dylib                   subtype_dealloc instance-delete-done
124753 python34764 libpython2.7.dylib                  instance_dealloc instance-delete-done
124754 python34764 libpython2.7.dylib                   subtype_dealloc instance-delete-start
124755 python34764 libpython2.7.dylib                  instance_dealloc instance-delete-start
124756 python34764 libpython2.7.dylib               PyType_GenericAlloc instance-new-done
124757 python34764 libpython2.7.dylib                    PyInstance_New instance-new-done
124758 python34764 libpython2.7.dylib               PyType_GenericAlloc instance-new-start
124759 python34764 libpython2.7.dylib                    PyInstance_New instance-new-start
124760 python34764 libpython2.7.dylib            PyEval_EvalFrameExReal line
```

So it builds and works at a basic level.

However, I did see some weirdness as well:

```
$ sudo dtrace -n 'python34764::: { printf("%s (%s:%d)", copyinstr(arg1), copyinstr(arg0), arg2) }' | grep test
dtrace: description 'python34764::: ' matched 13 probes
dtrace: error on enabled probe ID 4 (ID 124751: python34764:libpython2.7.dylib:collect:gc-start): invalid address (0x2) in action #2 at DIF offset 24
dtrace: error on enabled probe ID 3 (ID 124750: python34764:libpython2.7.dylib:collect:gc-done): invalid address (0xfffffffffffffffb) in action #1 at DIF offset 24
```

and

```
~/src/python-hg/cpython-2011$ sudo DYLD_LIBRARY_PATH=. dtrace -n 'python*::: { printf("%s (%s:%d)", copyinstr(arg1), copyinstr(arg0), arg2) }' -c 'python2.7 /Users/marca/python/test.py' > /dev/null
dtrace: description 'python*::: ' matched 29 probes
dtrace: pid 34907 has exited
dtrace: error on enabled probe ID 20 (ID 126731: python34907:libpython2.7.dylib:collect:gc-start): invalid address (0x2) in action #2 at DIF offset 24
dtrace: error on enabled probe ID 19 (ID 126730: python34907:libpython2.7.dylib:collect:gc-done): invalid address (0xfffffffffffffffb) in action #1 at DIF offset 24
```

On the other hand, some stuff appears to work sometimes:

```
~/src/python-hg/cpython-2011$ sudo DYLD_LIBRARY_PATH=. dtrace -n 'python*:::function-entry { printf("%s (%s:%d)", copyinstr(arg1), copyinstr(arg0), arg2) }' -c 'python2.7 /Users/marca/python/test.py'
dtrace: description 'python*:::function-entry ' matched 9 probes
Current working directory: /Users/marca/src/python-hg/cpython-2011
11
Current working directory: /Users/marca/src/python-hg/cpython-2011
11
Current working directory: /Users/marca/src/python-hg/cpython-2011
11
dtrace: pid 34953 has exited
CPU     ID                    FUNCTION:NAME
  2 125639 PyEval_EvalFrameExReal:function-entry <module> (/Users/marca/python/test.py:1)
  2 125639 PyEval_EvalFrameExReal:function-entry <module> (/Users/marca/python/marcsmath.py:1)
  2 125639 PyEval_EvalFrameExReal:function-entry test_func (/Users/marca/python/test.py:4)
  2 125639 PyEval_EvalFrameExReal:function-entry add (/Users/marca/python/marcsmath.py:1)
  2 125639 PyEval_EvalFrameExReal:function-entry test_func (/Users/marca/python/test.py:4)
  2 125639 PyEval_EvalFrameExReal:function-entry add (/Users/marca/python/marcsmath.py:1)
  2 125639 PyEval_EvalFrameExReal:function-entry test_func (/Users/marca/python/test.py:4)
  2 125639 PyEval_EvalFrameExReal:function-entry add (/Users/marca/python/marcsmath.py:1)
  2 125639 PyEval_EvalFrameExReal:function-entry _remove (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/_weakrefset.py:38)
  2 125639 PyEval_EvalFrameExReal:function-entry _remove (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/_weakrefset.py:38)
```

```
~/src/python-hg/cpython-2011$ sudo dtrace -n 'python*::: { printf("%s (%s:%d)", copyinstr(arg1), copyinstr(arg0), arg2) }' 2> /dev/null | grep 'function-entry.*pip'
### In another tab, do: "pip install --help" ###
  1 124748 PyEval_EvalFrameExReal:function-entry <module> (/Users/marca/.pythonbrew/pythons/Python-2.7.2/bin/pip:3)
  2 124748 PyEval_EvalFrameExReal:function-entry <module> (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/basecommand.py:1)
  2 124748 PyEval_EvalFrameExReal:function-entry <module> (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/commands/__init__.py:1)
  2 124748 PyEval_EvalFrameExReal:function-entry <module> (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/log.py:2)
  2 124748 PyEval_EvalFrameExReal:function-entry Logger (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/log.py:8)
  2 124748 PyEval_EvalFrameExReal:function-entry __init__ (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/log.py:25)
  2 124748 PyEval_EvalFrameExReal:function-entry <module> (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/baseparser.py:1)
  2 124748 PyEval_EvalFrameExReal:function-entry <module> (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/locations.py:1)
  2 124748 PyEval_EvalFrameExReal:function-entry running_under_virtualenv (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/locations.py:8)
  2 124748 PyEval_EvalFrameExReal:function-entry UpdatingDefaultsHelpFormatter (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/baseparser.py:12)
  2 124748 PyEval_EvalFrameExReal:function-entry ConfigOptionParser (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/baseparser.py:23)
  3 124748 PyEval_EvalFrameExReal:function-entry <module> (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/exceptions.py:1)
  3 124748 PyEval_EvalFrameExReal:function-entry InstallationError (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/exceptions.py:4)
  3 124748 PyEval_EvalFrameExReal:function-entry UninstallationError (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/exceptions.py:8)
  3 124748 PyEval_EvalFrameExReal:function-entry DistributionNotFound (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/exceptions.py:12)
  3 124748 PyEval_EvalFrameExReal:function-entry BadCommand (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/exceptions.py:16)
  3 124748 PyEval_EvalFrameExReal:function-entry <module> (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/util.py:1)
  3 124748 PyEval_EvalFrameExReal:function-entry _Inf (/Users/marca/.pythonbrew/pythons/Python-2.7.2/lib/python2.7/site-packages/pip-1.0.2-py2.7.egg/pip/util.py:119)
```

Marc, the MacOS X support is planned, but I want first to finish the Solaris support 100%. I am working with other people in being sure this patch works in a standard Solaris machine (my machines are heavily tuned, GNU tools installed, GCC, extra libraries, etc), specially under Sparc, that I can not check personally.

This work is progressing fine. I hope to have it done in a week or two.

After that, next step is MacOS, if I can convince a friend to spend a weekend at home with me :-).

BTW, as far as I know, DTrace port for MacOS X DOESN'T support "jstack();" at all. So that test must be skipped under MacOS.

Anyway, all of this is planned.

The gc-start/gc-done probe errors you are seeing are strange, but I can't investigate them until I start building under MacOS. Late March, I hope.

I assume your machine is x86 based, not PowerPC.

Marc, if you have a XMPP account (for instance, gtalk), we can chat online and work together on this. My JID is jcea@jabber.org. I am in Spain, so Central European Time timezone (GMT+1, +2 under DST).

Marc, the memory invalid accesses are because you are enabling all probes and printing three parameters, but each probe actually has a different number of parameters and different meaning for them. Current version:

"""
provider python {
    probe function__entry(const char *, const char *, int);
    probe function__return(const char *, const char *, int);
    probe instance__new__start(const char *, const char *);
    probe instance__new__done(const char *, const char *);
    probe instance__delete__start(const char *, const char *);
    probe instance__delete__done(const char *, const char *);
    probe line(const char *, const char *, int);
    probe gc__start(int);
    probe gc__done(long);
};
"""

In particular, this explain the weirdness in your gc-start/gc-done probes.

Can you run the testsuite with "./python Lib/test/regrtest.py -v test_dtrace.py"?. The stack dump test will fail for sure, because MacOS DTrace port doesn't support uhelpers at all.

5AM here. Time for some sleep!.

Hi Jesús,

Yes, I'm on an x86 machine. A MacBook Pro with OS X 10.6.8.

I'll try to hop on Google Talk during the week. I'm on the west coast of the U.S. (GMT-8) so it might be tricky to find a mutually good time.

Here's the result of the tests - like you said the stack test failed but everything else passed:

```
[last: 0] marca@SCML-MarcA:~/src/python-hg/cpython-2011$ sudo ~/custom/bin/python Lib/test/test_dtrace.py 
test_function_entry_return (__main__.DTraceTestsNormal) ... ok
test_garbage_collection (__main__.DTraceTestsNormal) ... ok
test_instance_creation_destruction (__main__.DTraceTestsNormal) ... ok
test_line (__main__.DTraceTestsNormal) ... ok
test_stack (__main__.DTraceTestsNormal) ... FAIL
test_verify_opcodes (__main__.DTraceTestsNormal) ... ok

======================================================================
FAIL: test_stack (__main__.DTraceTestsNormal)
...
```

Perhaps the test should be modified as follows:

```
[last: 0] marca@SCML-MarcA:~/src/python-hg/cpython-2011$ hg diff Lib/test/test_dtrace.py
diff -r b50130b35288 Lib/test/test_dtrace.py
--- a/Lib/test/test_dtrace.py	Wed Feb 22 02:15:47 2012 +0100
+++ b/Lib/test/test_dtrace.py	Sun Feb 26 22:56:03 2012 -0800
@@ -78,6 +78,9 @@
         self.assertEqual(actual_result, expected_result)
 
     def test_stack(self) :
+        if sys.platform == 'darwin':
+            raise unittest.SkipTest, "No jstack support on Mac OS X"
+
         dscript = """
 python$target:::function-entry
 /(copyinstr(arg0)=="%(path)s") &&
```

Then the result is:

```
[last: 0] marca@SCML-MarcA:~/src/python-hg/cpython-2011$ sudo ~/custom/bin/python Lib/test/test_dtrace.py 
test_function_entry_return (__main__.DTraceTestsNormal) ... ok
test_garbage_collection (__main__.DTraceTestsNormal) ... ok
test_instance_creation_destruction (__main__.DTraceTestsNormal) ... ok
test_line (__main__.DTraceTestsNormal) ... ok
test_stack (__main__.DTraceTestsNormal) ... skipped 'No jstack support on Mac OS X'
test_verify_opcodes (__main__.DTraceTestsNormal) ... ok

----------------------------------------------------------------------
Ran 6 tests in 0.561s

OK (skipped=1)
test_function_entry_return (__main__.DTraceTestsOptimize) ... ok
test_garbage_collection (__main__.DTraceTestsOptimize) ... ok
test_instance_creation_destruction (__main__.DTraceTestsOptimize) ... ok
test_line (__main__.DTraceTestsOptimize) ... ok
test_stack (__main__.DTraceTestsOptimize) ... skipped 'No jstack support on Mac OS X'
test_verify_opcodes (__main__.DTraceTestsOptimize) ... ok

----------------------------------------------------------------------
Ran 6 tests in 0.577s

OK (skipped=1)
```

By the way, I have some virtual machines set up for OpenIndiana b151A and FreeBSD 9.0, so you need some testing on those platforms, let me know.

All tests pass on OpenIndiana b151A (SunOS openindiana 5.11 oi_151a2 i86pc i386 i86pc Solaris).

Marc, OpenIndiana is one of the platforms I am testing myself :-).

If you can try FreeBSD 9.0, that would be amazing.

I have committed the skip of "jstack()" test in "darwin", since we know that the code is not actually ported to MacOS X.

The main complexity of supporting MacOS X was that "dtrace -G" used to fails under MacOS. Current MacOS releases simply ignore the flag. I don't know since when this is not an issue anymore. Can you test under older MacOS releases?. Is it OK to support this feature ONLY in recent OS releases?. AFAIK, "-G" was a problem with MacOS X 10.5. See http://markmail.org/message/5xrxt2w5m42nojkz

Have you tried both 32 and 64 bits builds?.

I have a handful of pending commits for vainilla Solaris 10 support, and I hope to be able to test SPARC builds in a few days.

PS: If you update your clone and have any issue, use as base a08c688aa99b, not "tip". I am going to rewrite some stuff and I rather prefer you have a "known" good codebase.

Thanks for your very helpful effort.

I get a build error on FreeBSD 9.0:

make: don't know how to make ./Include/phelper_offsets.h. Stop

Any ideas?

Re my comment in #154513, the following seems to fix that problem on FreeBSD 9.0:


[marca@freebsd9-0 ~/src/cpython-2011]$ hg diff Makefile.pre.in
diff -r 70dc1e48bd7f Makefile.pre.in
--- a/Makefile.pre.in	Mon Feb 27 22:43:17 2012 +0100
+++ b/Makefile.pre.in	Mon Feb 27 14:20:18 2012 -0800
@@ -632,7 +632,7 @@
 	else	touch $@ ; \
 	fi;
 
-Include/phelper_offsets.h: $(srcdir)/Include/phelper_offsets.c $(srcdir)/Python/ceval.o
+$(srcdir)/Include/phelper_offsets.h: $(srcdir)/Include/phelper_offsets.c $(srcdir)/Python/ceval.o
 	$(CC) $(PY_CFLAGS) -o $(srcdir)/Include/phelper_offsets \
 		$(srcdir)/Include/phelper_offsets.c
 	$(srcdir)/Include/phelper_offsets.sh $(DTRACE_NM) \

I'm now struggling with some other errors:

gcc -pthread -fno-strict-aliasing -g -O2 -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes  -I. -IInclude -I./Include  -DPy_BUILD_CORE  -c ./Modules/xxsubtype.c -o Modules/xxsubtype.o
if test "dtrace" != "" ; then  dtrace -o Python/dtrace.o -64  -C -G -s ./Include/pydtrace.d  Python/ceval.o Modules/gcmodule.o  Objects/classobject.o Objects/typeobject.o;  else    touch Python/dtrace.o ;  fi;
gcc -pthread -fno-strict-aliasing -g -O2 -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes  -I. -IInclude -I./Include  -DPy_BUILD_CORE -o ./Include/phelper_offsets  ./Include/phelper_offsets.c
./Include/phelper_offsets.sh OTHER  ./Python/ceval.o ./Include/phelper_offsets >  ./Include/phelper_offsets.h
if test "dtrace" != "" ; then  dtrace -o Python/phelper.o -DPHELPER -64  -I. -IInclude -I./Include -C -G -s ./Include/phelper.d ;  else	touch Python/phelper.o ;  fi;
dtrace: failed to compile script ./Include/phelper.d: line 3: useless declaration
*** Error code 1

Marc, check your email. I am online in Jabber/XMPP. My JID is jcea@jabber.org. Can you send me a chat message there?. Google demands that you start the communication, possibly to avoid IM spam.

MacOS 10.6 was released in August 2009. The code should compile there flawless with a couple of trivial changes, as proved by Marc.

Supporting compilation in MacOS 10.5 is doable but more difficult. Since this is an optional feature, not impacting python programs, I am tempted of not investing any time on it.

Note, however, that the compiled 10.6 version will provide full dtrace support in previous MacOS releases. The difficulty is in compilation, not at runtime.

Opinions?

Given that the current Mac OS is 10.7, and 10.8 was just announced, it seems reasonable to limit support to 10.6, if going back any further is more than a little bit of additional work.

IIRC, 10.6 is also the last release to support PowerPC, so going back that far does cover a lot of existing hardware.

Actually 10.5 was the last PowerPC release

Limiting to 10.6 and above seems entirely reasonable to me. I am one of the few folks that I know who is still on 10.6. Most of my friends are on 10.7.

Since OS X is primarily a desktop OS, I think people tend to upgrade more quickly compared to more of a server OS like Solaris. For instance, I stayed on 10.5 for a while but was eventually forced to upgrade to 10.6, because I wanted to do iOS development and the Xcode and developer SDK needed to do that required 10.6. That right there kind of tells you that even Apple is not really supporting 10.5 for development.

Also, if you target 10.6, I can test it for you. If you target 10.5, I don't have a 10.5 machine to test with.

So if it's at all hard to support 10.5, I'd say skip it and someone else can do it if they really need it. But I doubt that will happen.

I wanted to post an update on FreeBSD 9.0, which Jesús and I worked on a bit yesterday.

Maybe Jordan will chime in here with an answer to my FreeBSD problems. :-)

With a little bit of Makefile hackery (make it skip building the phelper stuff which was failing with a "useless declaration" error and which is for jstack which might not be supported on FreeBSD), I got Python to build with Jesús's patches.

But I couldn't actually dtrace anything with it.

And then I stepped back and tried to dtrace other programs to see if userland DTrace was working and I ran into all kinds of problems, including killing the traced program and a (reproduceable) kernel panic. Here's a question that I posted about it on the FreeBSD-questions mailing list:

http://lists.freebsd.org/pipermail/freebsd-questions/2012-February/238862.html

If I can get the FreeBSD DTrace support working without too much effort, then I'll do it, but if it's problematic, then I might skip it and focus on helping Jesús test his stuff on OS X and OpenIndiana.

[marca@freebsd9-0 ~]$ /home/marca/custom/bin/python
Python 2.7.2+ (dtrace-issue13405_2.7:e612f29478e3+, Feb 27 2012, 20:37:22) 
[GCC 4.2.1 20070831 patched [FreeBSD]] on freebsd9
Type "help", "copyright", "credits" or "license" for more information.
>>> 
[marca@freebsd9-0 ~]$ sudo dtrace -n 'pid$target:python::entry' -c /home/marca/custom/bin/python
Python 2.7.2+ (dtrace-issue13405_2.7:e612f29478e3+, Feb 27 2012, 20:37:22) 
[GCC 4.2.1 20070831 patched [FreeBSD]] on freebsd9
Type "help", "copyright", "credits" or "license" for more information.
>>> import os
>>> os.getpid()
2541
>>> 
dtrace: failed to control pid 2541: process exited with status 0


[marca@freebsd9-0 ~]$ ps auxww | grep python
marca       2546   0.0  2.3  27452   5668   1  S+    3:29AM   0:00.02 /home/marca/custom/bin/python
[marca@freebsd9-0 ~]$ sudo dtrace -n 'pid2546:python::entry'
[marca@freebsd9-0 ~]$ ps auxww | grep python
marca       2552   0.0  0.5  16460   1244   0  S+    3:29AM   0:00.00 grep python

In the above case, the python proces (pid 2546) died with:

>>> Killed: 9

Why would DTrace kill -9 the program it's tracing?

For anyone who is curious about the FreeBSD 9.0 DTrace userland problems I experienced, see http://www.freebsd.org/cgi/query-pr.cgi?pr=165541

Hey Jesús,

Let me know if you need any additional help testing.

Marc

Published diff from stock 2.7.3.

Cleanups and simplifications.

Marc, could you possible compile under MacOS X both 2.7 and 3.3 branches, both in 32 and 64 bits?.

The tags are:

dtrace-issue13405      <- 3.3a2+
dtrace-issue13405_2.7  <- 2.7.3

Let me know how is going. Please, document your build environment.

PHP 5.4.0 added DTRACE support:

http://fr2.php.net/ChangeLog-5.php

The python window for 3.3 closes mid june. Let's do not miss it this time :-).

Stan, anybody working in SystemTap support, could you possibly create a new issue in the tracker to track specifically stap support?. You can depend on this bug, and coordinate effort. Clone my repository and use it as base.

Thanks!.

> Stan, anybody working in SystemTap support, could you possibly
> create a new issue in the tracker to track specifically stap
> support?. You can depend on this bug, and coordinate effort. Clone
> my repository and use it as base.

I believe the only remotely-systemtap-specific stuff we suggested
would be useful would be the addition of that PyEval_GetFrame() value
as an extra argument for function entry/exit sdt.h calls.

I believe your patch already apprx. works against systemtap (and in
fact many dtrace idiosyncracies like asm("nop") are unnecessary here),
except for the inclusion of the /usr/bin/dtrace -G-generated header
file, as mentioned in <http://bugs.python.org/issue13405#msg149054>.

Do you think it is necessary to track that in a separate bug?

- FChE

Frank, if somebody provides a "diff" I can test under Ubuntu 10.04, I can try it myself.

This patch MUST be differential from my current patch (to be applied OVER it) and must cover EVERYTHING, from "./configure" to the test execution.

Anyway, "issues" in the tracker are free, and I rather prefer to have a separate issue, actually. You can copy the nosy list.

The "nop" issue seems to be related to SPARC branch slot. I don't have SPARC hardware to try, anymore :-(. Trying  with "friends", but it is moving slowly.

I've refreshed my SystemTap patch, and opened a new issue, issue #14776 to cover SystemTap.

Issue #4111 was originally opened on 2008-10-12 as "Add DTrace probes", and was generalized on 2009-12-08 to "Add Systemtap/DTrace probes".  That issue was closed on 2011-11-14 to be superceded by issue #13405 ("Add DTrace probes"), hence I opened the SystemTap RFE as a separate issue to this one.

As noted in issue #14776: I believe that although DTrace and SystemTap are similar, they are sufficiently different from each other that it's going to take separate work to support one or the other (and that the maintainers of the support for each within CPython are likely to be different people).  I hope that once one of them is merged, the other will become a lot easier to merge.

Hi jcea,

Sorry, I've been away from this for a while.

I'm getting undefined symbols now while trying to link:

```

(12:47pm) [last: 0] marca@scml-marca:~/src$ hg clone http://hg.python.org/cpython...
(12:55pm) [last: 0] marca@scml-marca:~/src$ cd cpython
[last: 0] marca@scml-marca:~/src/cpython$ hg tip
changeset:   77378:da5b370f41a1
branch:      2.7
tag:         tip
user:        Richard Oudkerk <shibturn@gmail.com>
date:        Wed Jun 06 19:01:14 2012 +0100
summary:     Issue #13854: Properly handle non-integer, non-string arg to SystemExit

[last: 0] marca@scml-marca:~/src/cpython$ curl -s http://bugs.python.org/file25203/4a072278b866.diff | patch -p1
patching file .hgignore
Hunk #1 succeeded at 81 (offset 8 lines).
patching file Doc/library/debug.rst
patching file Doc/library/dtrace.rst
patching file Include/code.h
patching file Include/pydtrace.d
patching file Include/pydtrace.h
patching file Include/pydtrace_offsets.c
patching file Include/pydtrace_offsets.sh
patching file Lib/test/dtrace_sample.py
patching file Lib/test/test_dtrace.py
patching file Makefile.pre.in
Hunk #2 succeeded at 462 (offset 1 line).
Hunk #3 succeeded at 491 (offset 1 line).
Hunk #4 succeeded at 502 (offset 1 line).
Hunk #5 succeeded at 607 (offset 17 lines).
Hunk #6 succeeded at 733 (offset 19 lines).
Hunk #7 succeeded at 1429 (offset 45 lines).
Hunk #8 succeeded at 1461 (offset 45 lines).
patching file Modules/dtracemodule.c
patching file Modules/gcmodule.c
Hunk #2 FAILED at 791.
Hunk #3 succeeded at 1059 with fuzz 1 (offset 112 lines).
1 out of 3 hunks FAILED -- saving rejects to file Modules/gcmodule.c.rej
patching file Objects/codeobject.c
patching file Objects/frameobject.c
Hunk #1 succeeded at 714 (offset 2 lines).
patching file Objects/typeobject.c
patching file Python/ceval.c
Hunk #9 succeeded at 3149 (offset 7 lines).
Hunk #10 succeeded at 3842 (offset 12 lines).
Hunk #11 succeeded at 3911 (offset 12 lines).
patching file configure
patching file configure.ac
patching file pyconfig.h.in
patching file setup.py
Hunk #1 succeeded at 575 (offset 4 lines).


[last: 0] marca@scml-marca:~/src/cpython$ ./configure --enable-framework && make
...
gcc -o Python.framework/Versions/3.3/Python   -dynamiclib \
          -all_load libpython3.3m.a -Wl,-single_module \
          -install_name /Library/Frameworks/Python.framework/Versions/3.3/Python \
          -compatibility_version 3.3 \
          -current_version 3.3 \
          -framework CoreFoundation -ldl  -framework CoreFoundation;
Undefined symbols:
  "_PYTHON_LINE_ENABLED", referenced from:
      _PyEval_EvalFrameEx in libpython3.3m.a(ceval.o)
      _PyEval_EvalFrameEx in libpython3.3m.a(ceval.o)
      _PyEval_EvalFrameEx in libpython3.3m.a(ceval.o)
      _PyEval_EvalFrameEx in libpython3.3m.a(ceval.o)
      _PyEval_EvalFrameEx in libpython3.3m.a(ceval.o)
```

The 2.7 patch doesn't apply cleanly for me against the latest on the 2.7 branch:

[last: 0] marca@scml-marca:~/src$ hg clone http://hg.python.org/cpython && cd cpython && hg update 2.7 && hg branch && hg tip && curl -s http://bugs.python.org/file25192/aa2dcffa267f.diff | patch -p1
destination directory: cpython
requesting all changes
adding changesets
adding manifests
adding file changes
added 77379 changesets with 172430 changes to 9646 files (+1 heads)
updating to branch default
3917 files updated, 0 files merged, 0 files removed, 0 files unresolved
3574 files updated, 0 files merged, 945 files removed, 0 files unresolved
2.7
changeset:   77378:da5b370f41a1
branch:      2.7
tag:         tip
user:        Richard Oudkerk <shibturn@gmail.com>
date:        Wed Jun 06 19:01:14 2012 +0100
summary:     Issue #13854: Properly handle non-integer, non-string arg to SystemExit

patching file .hgignore
patching file Doc/library/debug.rst
patching file Doc/library/dtrace.rst
patching file Include/code.h
patching file Include/pydtrace.d
patching file Include/pydtrace.h
patching file Include/pydtrace_offsets.c
patching file Include/pydtrace_offsets.sh
patching file Lib/test/dtrace_sample.py
patching file Lib/test/test_dtrace.py
patching file Makefile.pre.in
patching file Modules/dtracemodule.c
patching file Modules/gcmodule.c
Hunk #2 succeeded at 873 (offset 51 lines).
Hunk #3 succeeded at 1038 (offset 54 lines).
patching file Objects/classobject.c
Hunk #2 succeeded at 557 (offset 10 lines).
Hunk #3 succeeded at 622 (offset 10 lines).
Hunk #4 succeeded at 676 (offset 10 lines).
Hunk #5 succeeded at 758 (offset 10 lines).
patching file Objects/codeobject.c
patching file Objects/typeobject.c
Hunk #4 succeeded at 931 (offset 5 lines).
patching file Python/ceval.c
patching file Python/sysmodule.c
patching file configure
Hunk #1 succeeded at 619 (offset 8 lines).
Hunk #2 succeeded at 768 (offset 8 lines).
Hunk #3 succeeded at 1444 (offset 8 lines).
Hunk #4 FAILED at 2616.
Hunk #5 FAILED at 3548.
Hunk #6 FAILED at 3663.
Hunk #7 FAILED at 3706.
Hunk #8 FAILED at 3765.
Hunk #9 FAILED at 3817.
Hunk #10 FAILED at 4360.
Hunk #11 FAILED at 6713.
Hunk #12 FAILED at 6746.
Hunk #13 FAILED at 6779.
Hunk #14 FAILED at 6812.
Hunk #15 FAILED at 6845.
Hunk #16 FAILED at 6878.
Hunk #17 FAILED at 6911.
Hunk #18 FAILED at 6944.
Hunk #19 FAILED at 6977.
Hunk #20 FAILED at 7037.
Hunk #21 FAILED at 7098.
Hunk #22 FAILED at 7159.
Hunk #23 FAILED at 7207.
Hunk #24 FAILED at 7248.
Hunk #25 FAILED at 7310.
Hunk #26 FAILED at 7381.
Hunk #27 succeeded at 9464 (offset 8 lines).
Hunk #28 FAILED at 12456.
Hunk #29 FAILED at 12508.
Hunk #30 FAILED at 12627.
Hunk #31 FAILED at 12893.
Hunk #32 FAILED at 14693.
Hunk #33 FAILED at 15008.
Hunk #34 FAILED at 15036.
Hunk #35 FAILED at 15063.
31 out of 35 hunks FAILED -- saving rejects to file configure.rej
can't find file to patch at input line 2128
Perhaps you used the wrong -p or --strip option?
The text leading up to this was:
--------------------------
|diff -r 70274d53c1dd -r aa2dcffa267f configure.in
|--- a/configure.in	Mon Apr 09 19:04:04 2012 -0400
|+++ b/configure.in	Thu Apr 12 12:51:51 2012 +0200
--------------------------
File to patch:

If I do `/configure --with-dtrace --enable-framework && make` then I get:

```
...
gcc -c -fno-strict-aliasing -fno-common -dynamic -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes    -I. -I./Include    -DPy_BUILD_CORE -o Modules/gcmodule.o Modules/gcmodule.c
Modules/gcmodule.c:1088: error: conflicting types for ‘collect’
Modules/gcmodule.c:849: error: previous definition of ‘collect’ was here
Modules/gcmodule.c: In function ‘collect’:
Modules/gcmodule.c:1093: warning: implicit declaration of function ‘collect2’
make: *** [Modules/gcmodule.o] Error 1
```

I hacked around the previous error (duplicate definitions of `collect`) and then ran into:

gcc -fno-strict-aliasing -fno-common -dynamic -DNDEBUG -g -fwrapv -O3 -Wall -Wstrict-prototypes    -I. -I./Include    -DPy_BUILD_CORE -o ./Include/pydtrace_offsets \
		./Include/pydtrace_offsets.c
./Include/pydtrace_offsets.c: In function ‘main’:
./Include/pydtrace_offsets.c:26: warning: format ‘%d’ expects type ‘int’, but argument 2 has type ‘long int’
./Include/pydtrace_offsets.c:29: warning: format ‘%d’ expects type ‘int’, but argument 2 has type ‘long unsigned int’
./Include/pydtrace_offsets.c:31: warning: implicit declaration of function ‘offsetof’
./Include/pydtrace_offsets.c:31: error: expected expression before ‘PyCompactUnicodeObject’
./Include/pydtrace_offsets.c:33: error: expected expression before ‘PyCompactUnicodeObject’
make: *** [Include/pydtrace_offsets.h] Error 1

I was able to fix this by adding "#include <stddef.h>".

Marc, please, check your GTalk/XMPP window :-)

Thanks to Marc Abramowitz huge help and support, current patch builds and works perfectly fine under:

1. x86 32 and 64 bits, static and shared library, Solaris 10.

2. x86 32 and 64 bits, static and shared library, OpenSolaris derivatives (Solaris 11, Openindiana)

3. x86 32 and 64 bits, static and shared library, Mac OS X, recent versions.

Pending stuff:

1. SPARC CPU testing.

2. FreeBSD (the custom buildbot we have was not compiled with the "right" kernel flags).

Could anybody help in those areas?.

@jcea I am the owner of the Solaris 11 buildslave[1]. I have configured the build user to have dtrace privileges if you need to run additional tests against it. Let me know if you encounter any additional issues with this system.


1)http://buildbot.python.org/all/builders/x86%20Solaris%2011%20custom/builds/3

I need to pass a "--with-dtrace" to the buildbot configure. How can I do it, beside faking it manipulating the pushed "configure" script?.

> I need to pass a "--with-dtrace" to the buildbot configure. How can I
> do it, beside faking it manipulating the pushed "configure" script?.

This is done on the buildmaster. I just did the change, can you try
again?

Antoine, thanks.

Antoine, the Solaris 11 custum buildbot is not getting the "--with-dtrace" configure parameter. Check which configuration have you changed :-?

"""
/configure --with-pydebug --with-system-ffi
 in dir /home/bpython/buildarea/custom.venus-solaris/build (timeout 1200 secs)
 watching logfiles {}
 argv: ['./configure', '--with-pydebug', '--with-system-ffi']
"""

> Antoine, the Solaris 11 custum buildbot is not getting the "--with-
> dtrace" configure parameter. Check which configuration have you changed 
> :-?

Well, I thought you meant the new FreeBSD buildbots. I'm gonna change the Solaris bb too.

Justin, I can compile and run the tests fine in my Solaris 11 virtual machine, both in 32 and 64 bits and both static and dynamic.

I am using GCC, and you are using Sun Studio.

http://buildbot.python.org/all/builders/x86%20Solaris%2011%20custom/builds/17/steps/compile/logs/stdio

I was wondering if you have Jabber/XMPP (mine: jcea@jabber.org) so we can talk about this in realtime, and do some "remote keyboard" test.

On OS X 10.8 with Xcode only (no command line tools), I get the following err (when using clang or when using llvm-gcc):

```
dtrace: failed to compile script ./Include/pydtrace.d: Preprocessor not found
make: *** [Include/pydtrace.h] Error 1
```

At homebrew we optionally try to apply your patch to python https://github.com/mxcl/homebrew/pull/14343.

I'd really like to be able to make the "Command Line Tools for Xcode" optional.

Note, there is no "cpp" for clang. Usually, the "CC=/path/to/clang" just works. (I have seen "CPP = $CC -E" before, but that did *not* do the trick here).

Any ideas?

Samuel, the program complaining about not being able to find the C Preprocessor is the system "dtrace" executable. Looks like a dependency there.

To check this hypotesis, create a file called "a.d", with the following content:

"""
provider test {
  probe abc(int);
};

"""

and try to generate the header file with the following command:

"""
dtrace -C -h -s a.d
"""

If that command complains about being unable to find the C Preprocessor, well, you need a C Preprocessor.

If dtrace doesn't obey environment variables pointing to the preprocessor, that would be a dtrace bug. You could create a symbolic link to "clang" executable, but that would be an ugly hack.

I did your test. Thank you! 
You are absolutely right, it seems, dtrace does not honor "CPP" or "PATH" or any other flags and bluntly looks in a hard-coded location. It's not up to you to patch that.

The obvious workaround w.r.t. dtrace not finding the preprocessor is to install the command-line tools for xcode, which you can do from Xcode's preferences.

something else to try (before installing the commandline tools): add $(dirname $(xcrun -find cpp)) to the search path of the shell:

bash$ PATH="${PATH}:$(dirname $(xcrun -find cpp))"

This adds the directory in the Xcode bundle that contains the command-line tools to the search path of the shell, and might make it possible for dtrace to find the preprocessor (depending on how dtrace is coded). If that works this trick could be added to the build process, we already do something similar to locate the compiler in the configure script.

dtrace ignores PATH and CC and CPP. I tried that already :/

Of course I could just install the command line tools. But still it's a shame since all the tools are already there.

It's rather annoying that dtrace doesn't honor the PATH variable, and when you run the strings command on /usr/lib/libdtrace.dylib you'll see that it hardcodes the use of gcc (not even cpp or clang).

I've filed radar 12196604 in Apple's tracker, although it is unlikely that this will help. BTW. You (Samuel) could also file a bugreport with Apple, the more people do this the higher the change that they will fix this.

OpenIndiana custom buildbots, 32 and 64 bits, SUCCESFULL:

2.7 branch:

32 bits:
http://buildbot.python.org/all/builders/x86%20OpenIndiana%20custom/builds/6

64 bits:
http://buildbot.python.org/all/builders/AMD64%20OpenIndiana%20custom/builds/8

3.3 branch:

32 bits:
http://buildbot.python.org/all/builders/x86%20OpenIndiana%20custom/builds/7

64 bits:
http://buildbot.python.org/all/builders/AMD64%20OpenIndiana%20custom/builds/9

Waiting for Solaris 11 custom buildbot to come online again :)

Nice to see this moving along as I helped Jesús a while back with some testing on OS X and FreeBSD. The buildbots in particular sound like a great asset.

Let me know if I can help again with testing, though it looks like the basics are pretty well-covered by the buildbots.

Marc, you just reminded me I need to ask antoine to re-create the custom DTrace builder that passes --with-dtrace, thanks :)

I've been keeping both of the FreeBSD (9.x and 10.x) buildslaves as close to HEAD as possible with frequent world updates, which have been receiving a lot of DTrace love lately.

I also note your follow-up on the PR you submitted, if I can help you or Jesús make progress on this, don't hesitate to let me know.

> Marc, you just reminded me I need to ask antoine to re-create the
> custom DTrace builder that passes --with-dtrace, thanks :)

Well, I don't think it makes a lot of sense to re-create it, until
DTrace support is integrated.

antoine, is it possible test/pass --with-dtrace on a buildbot without including it in the master build configuration?

If not, I'm happy to create a special (dedicated) slave for Jesús so he can continue to test his branch at leisure without messing up the existing slave configurations. 

That will also remove the dependency on me, and our inconvenient timezone overlap for communication :)

> antoine, is it possible test/pass --with-dtrace on a buildbot without
> including it in the master build configuration?
> 
> If not, I'm happy to create a special (dedicated) slave for Jesús so
> he can continue to test his branch at leisure without messing up the
> existing slave configurations.

If it's just for Jesus, perhaps it's easier to give him dedicated ssh
access to the machine :-) Buildbots are really meant to regression-test
CPython, not offer workspaces to developers (I mean, the latter would
be cool, but the current manual management of buildbots doesn't make it
very workable).

I opened a bug for tracking progress of development of the combined dtrace and systemtap support: http://bugs.python.org/issue21590