Functions exposed using boost::python not reported by the python profiler

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

Functions exposed using boost::python not reported by the python profiler

Arnaud Espanel
Hi --
When running a python program through the python profiler, calls to a
function exposed directly through C python api are reported, but not
the calls to a function exposed through boost::python. I'd like to see
boost::python calls reported on their own as well... but have not
managed to.
To demonstrate this, a simple "greet" fonction that returns a string
has been implemented in two versions. The first implementation ("cext"
module) has been exposed directly using python C api. The second
implementation ("bpyext" module)  has been exposed using boost::python
(the corresponding source code is at the end of this message).

When profiling these functions:

>>> import cProfile as profile
>>> profile.run('cext.greet()')
         3 function calls in 0.000 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {cext.greet}
        1    0.000    0.000    0.000    0.000 {method 'disable' of
'_lsprof.Profiler' objects}


>>> profile.run('bpyext.greet()')
         2 function calls in 0.000 CPU seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of
'_lsprof.Profiler' objects}

We can see that the call to the C extension module (cext.greet) get
reported, but not the call to the boost::python extension
(bpyext.greet). Looking at how the profile module works, the profile
module is notified by the python interpreter on each function
call/return. This notification happens through the function set by
os.setprofile(function). Let's provide some simple "profiler" function
that just prints whenever it is called by the interpreter:

>>> import cext, bpyext, sys
>>> def profiler(frame,event,arg):
...     print 'PROF %r %r' % (event, arg)
...
>>> sys.setprofile(profiler)
PROF 'return' None
>>> cext.greet()
PROF 'call' None
PROF 'c_call' <built-in function greet>
PROF 'c_return' <built-in function greet>
'hello from C'
PROF 'return' None
>>> bpyext.greet()
PROF 'call' None
'Hello from boost::python'
PROF 'return' None

It works as expected for the C extension (we can see the
c_call/c_return events), but no events are triggered when the
boost::python function is called. Why is this the case? Is there
something that can be done in order to trigger these c_call/c_return
events for boost::python extensions?

Thanks,
Arnaud


For reference, here is the code of the C/boost::python modules. Tests
were done on Linux x86_64, using python 2.6.5 and boost 1.40.0
======================== cext.c ========================
include <Python.h>

static PyObject *
greet(PyObject *self, PyObject *args)
{
  return Py_BuildValue("s", "hello from C");
}

static PyMethodDef CextMethods[] = {
    {"greet",  greet, METH_VARARGS,
     "Say hi"},
    {NULL, NULL, 0, NULL}
};

PyMODINIT_FUNC
initcext(void)
{
  (void) Py_InitModule("cext", CextMethods);
}

======================= bpyext.cpp ======================
#include <string>
#include <boost/python.hpp>

std::string greet() {
    return "Hello from boost::python";
}

using namespace boost::python;

BOOST_PYTHON_MODULE(bpyext) {
    def("greet", &greet)
    ;
}
_______________________________________________
Cplusplus-sig mailing list
[hidden email]
http://mail.python.org/mailman/listinfo/cplusplus-sig
Reply | Threaded
Open this post in threaded view
|

Re: Functions exposed using boost::python not reported by the python profiler

Jim Bosch-2
On 08/09/2011 03:57 PM, Arnaud Espanel wrote:
> Hi --
> When running a python program through the python profiler, calls to a
> function exposed directly through C python api are reported, but not
> the calls to a function exposed through boost::python. I'd like to see
> boost::python calls reported on their own as well... but have not
> managed to.

This is my first look into how Python profiling works, but I think the
basic problem is that Boost.Python-wrapped functions are really just
callable objects.  Their implementation doesn't use the standard Python
C-API procedure for exposing functions (which requires lots of static
variables), and they of course aren't pure Python functions either.  So
none of the triggers for trace events within Python itself every get called.

The solution to is probably to modify the internals of Boost.Python's
special Function type to explicitly trigger those events.  That's
probably what the behavior of Boost.Python should be, and I suspect it
would be a fairly small change to make.

It's worrying that the functions that trigger the events don't appear to
be a documented part of the Python C-API, though.  The only way to
figure out how to do it would be to dive into the Python code itself,
and hope those functions are stable between Python releases.

Jim




> To demonstrate this, a simple "greet" fonction that returns a string
> has been implemented in two versions. The first implementation ("cext"
> module) has been exposed directly using python C api. The second
> implementation ("bpyext" module)  has been exposed using boost::python
> (the corresponding source code is at the end of this message).
>
> When profiling these functions:
>
>>>> import cProfile as profile
>>>> profile.run('cext.greet()')
>           3 function calls in 0.000 CPU seconds
>
>     Ordered by: standard name
>
>     ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>          1    0.000    0.000    0.000    0.000<string>:1(<module>)
>          1    0.000    0.000    0.000    0.000 {cext.greet}
>          1    0.000    0.000    0.000    0.000 {method 'disable' of
> '_lsprof.Profiler' objects}
>
>
>>>> profile.run('bpyext.greet()')
>           2 function calls in 0.000 CPU seconds
>
>     Ordered by: standard name
>
>     ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>          1    0.000    0.000    0.000    0.000<string>:1(<module>)
>          1    0.000    0.000    0.000    0.000 {method 'disable' of
> '_lsprof.Profiler' objects}
>
> We can see that the call to the C extension module (cext.greet) get
> reported, but not the call to the boost::python extension
> (bpyext.greet). Looking at how the profile module works, the profile
> module is notified by the python interpreter on each function
> call/return. This notification happens through the function set by
> os.setprofile(function). Let's provide some simple "profiler" function
> that just prints whenever it is called by the interpreter:
>
>>>> import cext, bpyext, sys
>>>> def profiler(frame,event,arg):
> ...     print 'PROF %r %r' % (event, arg)
> ...
>>>> sys.setprofile(profiler)
> PROF 'return' None
>>>> cext.greet()
> PROF 'call' None
> PROF 'c_call'<built-in function greet>
> PROF 'c_return'<built-in function greet>
> 'hello from C'
> PROF 'return' None
>>>> bpyext.greet()
> PROF 'call' None
> 'Hello from boost::python'
> PROF 'return' None
>
> It works as expected for the C extension (we can see the
> c_call/c_return events), but no events are triggered when the
> boost::python function is called. Why is this the case? Is there
> something that can be done in order to trigger these c_call/c_return
> events for boost::python extensions?
>
> Thanks,
> Arnaud
>
>
> For reference, here is the code of the C/boost::python modules. Tests
> were done on Linux x86_64, using python 2.6.5 and boost 1.40.0
> ======================== cext.c ========================
> include<Python.h>
>
> static PyObject *
> greet(PyObject *self, PyObject *args)
> {
>    return Py_BuildValue("s", "hello from C");
> }
>
> static PyMethodDef CextMethods[] = {
>      {"greet",  greet, METH_VARARGS,
>       "Say hi"},
>      {NULL, NULL, 0, NULL}
> };
>
> PyMODINIT_FUNC
> initcext(void)
> {
>    (void) Py_InitModule("cext", CextMethods);
> }
>
> ======================= bpyext.cpp ======================
> #include<string>
> #include<boost/python.hpp>
>
> std::string greet() {
>      return "Hello from boost::python";
> }
>
> using namespace boost::python;
>
> BOOST_PYTHON_MODULE(bpyext) {
>      def("greet",&greet)
>      ;
> }
> _______________________________________________
> Cplusplus-sig mailing list
> [hidden email]
> http://mail.python.org/mailman/listinfo/cplusplus-sig

_______________________________________________
Cplusplus-sig mailing list
[hidden email]
http://mail.python.org/mailman/listinfo/cplusplus-sig
Reply | Threaded
Open this post in threaded view
|

Re: Functions exposed using boost::python not reported by the python profiler

Stefan Seefeld-2
On 08/09/2011 08:23 PM, Jim Bosch wrote:

> On 08/09/2011 03:57 PM, Arnaud Espanel wrote:
>> Hi --
>> When running a python program through the python profiler, calls to a
>> function exposed directly through C python api are reported, but not
>> the calls to a function exposed through boost::python. I'd like to see
>> boost::python calls reported on their own as well... but have not
>> managed to.
>
> This is my first look into how Python profiling works, but I think the
> basic problem is that Boost.Python-wrapped functions are really just
> callable objects.  Their implementation doesn't use the standard
> Python C-API procedure for exposing functions (which requires lots of
> static variables), and they of course aren't pure Python functions
> either.  So none of the triggers for trace events within Python itself
> every get called.
>
> The solution to is probably to modify the internals of Boost.Python's
> special Function type to explicitly trigger those events.  That's
> probably what the behavior of Boost.Python should be, and I suspect it
> would be a fairly small change to make.
>
> It's worrying that the functions that trigger the events don't appear
> to be a documented part of the Python C-API, though.  The only way to
> figure out how to do it would be to dive into the Python code itself,
> and hope those functions are stable between Python releases.

I would actually go one step further and report this issue (of
undocumented / non-public functions required for tracing) to the Python
bug tracker (http://bugs.python.org), and hope that this gets properly
addressed.

    Stefan

--

      ...ich hab' noch einen Koffer in Berlin...

_______________________________________________
Cplusplus-sig mailing list
[hidden email]
http://mail.python.org/mailman/listinfo/cplusplus-sig