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/).