15.13 Module: Allowing the Python Profiler to Profile C Modules

Credit: Richie Hindle

Profiling is the most crucial part of optimization. What you can't measure, you cannot control. This definitely applies to your program's running time. To make sure that Python's standard profile module can also measure the time spent in C-coded extensions, you need to wrap those extensions with the module shown in Example 15-1. An alternative to the approach in this module is to use the new Hotshot profiler that ships with Python 2.2 and later.

This module lets you take into account time spent in C modules when profiling your Python code. Normally, the profiler profiles only Python code, so it's difficult to find out how much time is spent accessing a database, running encryption code, sleeping, and so on. This module makes it easy to profile C code as well as Python code, giving you a clearer picture of how your application is spending its time.

This module also demonstrates how to create proxy objects at runtime that intercept calls between preexisting pieces of code. Furthermore, it shows how to use the new module to create new functions on the fly. We could do many of these things in a somewhat lightweight fashion, but systematically using the new module is a good way to demystify its reputation for difficulty.

Here's a small piece of code using the rotor encryption module:

import rotor, profile
r = rotor.newrotor('key')
profile.run("r.encrypt('Plaintext')")

This won't produce any profiler output for the encrypt method, because the method is implemented in C. The profilewrap module presented in this recipe can wrap the rotor object in dynamically generated Python code that is accessible to the profiler, like this:

import rotor, profile, profilewrap
r = rotor.newrotor('key')
r = profilewrap.wrap(r) # profilewrap in action, replacing
                        # 'r' with a profilable wrapper
profile.run("r.encrypt('Plaintext')")

You can now see an entry in the profiler output that is something like:

1 0.003 0.003 0.003 0.003 PW_rotor.py:1(encrypt)

The filename PW_rotor.py is derived from the name of the object or module to which the method belongs. PW_rotor.py doesn't actually exist, but that little detail does not disturb the profiler.

In addition to objects, you can wrap individual functions (e.g., sleep=profilewrap.wrap(time.sleep)) and whole modules (e.g., os=profilewrap.wrap(os)). Note that wrapping a module wraps only the functions that the module exports; it doesn't automatically wrap objects created by those functions. See _profileMe in Example 15-1.

Example 15-1. Allowing the Python profiler to profile C modules

""" profilewrap.py:
Wraps C functions, objects and modules in dynamically generated Python code
so you can profile them. Here's an example using the rotor module:
>>> import profilewrap, rotor, profile
>>> r = profilewrap.wrap(rotor.newrotor('key'))
>>> profile.run("r.encrypt('Plaintext')")
This will produce output including something like this:
    1    0.003    0.003    0.003    0.003 PW_rotor.py:1(encrypt)

See the _profileMe function for examples of wrapping C functions, objects, and
modules. Run profilewrap.py to see the output from profiling _profileMe. """

import new, types

def _functionProxy(f, *args, **kwargs):
    """ The prototype for the dynamic Python code wrapping each C function """
    return apply(f, args, kwargs)

class _ProfileWrapFunction:
    """ A callable object that wraps each C function we want to profile. """
    def _ _init_ _(self, wrappedFunction, parentName="unnamed"):
        # Build the code for a new wrapper function, based on _functionProxy
        filename = "PW_%s.py" % parentName
        name = wrappedFunction._ _name_ _
        c = _functionProxy.func_code
        newcode = new.code(c.co_argcount, c.co_nlocals, c.co_stacksize,
                           c.co_flags, c.co_code, c.co_consts, c.co_names,
                           c.co_varnames, filename, name, 1, c.co_lnotab)

        # Create a proxy function using the new code
        self._wrapper = new.function(newcode, globals(  ))
        self._wrappedFunction = wrappedFunction

    def _ _call_ _(self, *args, **kwargs):
        return apply(self._wrapper, (self._wrappedFunction,) + args, kwargs)

class _ProfileWrapObject:
    """ A class that wraps an object or a module and dynamically creates a
       _ProfileWrapFunction for each method. Wrappers are cached for speed. """
    def _ _init_ _(self, wrappedObject):
        self._wrappedObject = wrappedObject
        self._cache = {}

    def _ _getattr_ _(self, attrName):
        # Look for a cached reference to the attribute. If it isn't there,
        # fetch it from the wrapped object.
        notThere = 'Not there'
        returnAttr = self._cache.get(attrName, notThere)
        if returnAttr is notThere:
            attr = getattr(self._wrappedObject, attrName, notThere)
            if attr is notThere:
                # The attribute is missing - let it raise an AttributeError
                getattr(self._wrappedObject, attrName)

            # We wrap only C functions, which have the BuiltinMethodType type
            elif isinstance(attr, types.BuiltinMethodType):
                # Base the fictitious filename on the module or class name
                if isinstance(self._wrappedObject, types.ModuleType):
                    objectName = self._wrappedObject._ _name_ _
                else:
                    objectName = type(self._wrappedObject)._ _name_ _
                returnAttr = _ProfileWrapFunction(attr, objectName)
                self._cache[ attrName ] = returnAttr

            # All non-C-function attributes are returned directly
            else:
                returnAttr = attr

        return returnAttr

def wrap(wrappee):
    """ Wrap the given object, module, or function in a Python wrapper. """
    if isinstance(wrappee, types.BuiltinFunctionType):
        return _ProfileWrapFunction(wrappee)
    else:
        return _ProfileWrapObject(wrappee)

def _profileMe(  ):
    # Wrap a built-in C function
    wrappedEval = wrap(eval)
    print wrappedEval('1+2*3')

    # Replace a C module with its wrapped equivalent
    import os
    os = wrap(os)
    print os.getcwd(  )

    # Wrap a C object
    import rotor
    r = wrap(rotor.newrotor('key'))
    print repr(r.encrypt('Plaintext'))

if _ _name_ _ == '_ _main_ _':
    import profile
    profile.run('_profileMe(  )')

15.13.1 See Also

No discussion of Python profiling is complete without mentioning the new Python profiler, HotShot, which, as of this writing, is not documented in the standard documentation; see Fred Drake's talk about HotShot, available from his home page (http://starship.python.net/crew/fdrake/).