[C++-sig] Functions exposed using boost::python not reported by the python profiler

[Jim Bosch]

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
> Cplusplus-sig at python.org
> http://mail.python.org/mailman/listinfo/cplusplus-sig