I received a request today to write a post about profiling C extensions in Python and here it is. I'm going to show you a little module that I wrote that acts as an interface layer for extensions by explaining how I made it. To begin with we need something to profile, to keep it simple we'll use the standard library:

# test.py
import time

time.sleep(5)

This is a good function to profile because we can guess the answer pretty well. What needs to happen is that the sleep function be replaced by a sleep function that profiles. We can do this with a decorator style function. If you haven't come across decorators before then there is a good introduction here.

# profile.py
import time

def profile_decorator(fn):
    def profiled(*args):
        start_time = time.time()
        res = fn(*args)
        print "function '%s.%s' with args '%s' took %f seconds" %(
            fn.__module__, fn.__name__, str(args), time.time() - start_time)
        return res
    profiled.__name__ = fn.__name__
    profiled.__module__ = fn.__module__
    return profiled

We can test that this works quite easily by writing a function and decorating it.

# test.py
import profile, time

@profile.profile_decorator
def run():
	time.sleep(5)

run()

Output:

function '__main__.run' with args '()' took 5.005149 seconds

Good, it works and this fine for Python functions that you've written, but it would be better if you could apply it to any function. The next thing we need is a function to apply this decorator to functions that already exist and replace there definitions with our new ones. How about:

def profile_function(function):
    sys.modules[function.__module__].__dict__[function.__name__] = (
        profile_decorator(function))

If you put profile_function in profile.py and add sys to the imports then we can update test.py to:

# test.py
import time, profile

profile.profile_function(time.sleep)

time.sleep(5)

Output:

function 'time.sleep' with args '(5,)' took 5.005155 seconds

Finally, profiling whole modules would be nice. A function like this will do that:

function_types = (types.FunctionType, types.BuiltinFunctionType)

def profile_module(module):
	for k in module.__dict__:
		if isinstance(module.__dict__[k], function_types):
			profile_function(module.__dict__[k])

Now you can profile functions to your heart's content, (so long as you add types to the imports list). Unfortunately, you can't use this function on time as it'll enter a recursive loop. The only thing missing is profiling methods, but it shouldn't be difficult to add if you need it. That just about wraps things up. All the code is lincensed under the BSD license, if you use any of it and make improvements or have comments then I'd like to hear from you, my email address is on the about page. Thanks for reading.

Full listing:

# profile.py
import time, sys, types

def profile_decorator(fn):
	def profiled(*args):
		start_time = time.time()
		res = fn(*args)
		print "function '%s.%s' with args '%s' took %f seconds" %(
			fn.__module__, fn.__name__, str(args), time.time() - start_time)
		return res
	profiled.__name__ = fn.__name__
	profiled.__module__ = fn.__module__
	return profiled

def profile_function(function):
	sys.modules[function.__module__].__dict__[function.__name__] = (
		profile_decorator(function))

function_types = (types.FunctionType, types.BuiltinFunctionType)

def profile_module(module):
	for k in module.__dict__:
		if isinstance(module.__dict__[k], function_types):
			profile_function(module.__dict__[k])