I don’t really like to put print statements in my code in order to do debugging. Actually the only thing I hate more is putting get-time-like functions before and after certain part of code. And then subtracting after with before and output the result. Wouldn’t it be nice to have a tool like gprof for debugging Django applications?
You can use one of the python’s module named hotshot, high performance logging profiler. How to use it you can read on its presentation site. Here I will only mention that its statistics function (hotshot.stats) outputs results to the standard output.
Let’s decide we will trigger the profiler on any url and output its results in the browser by appending profile attribute in the url query string. In order to intercept that attribute we create a so-called view middleware. In this middleware we inspect the url that was used to call a certain view.
Now, in middleware code we just have to check whether there is a GET attribute named profile in the query string (e.g. http://example.com/some/path/?profile). If there is one we create the Profile object, use it to make a call to the actual view, and then output statistics via returning HttpResponse. Since statistics are output to stdout we redirect it to StringIO to be able to display it in the response.
If no such attribute exists None is returned, and normal procedure of calling the default view takes place. When you put it all together the middleware code looks like the following:
from django.http import HttpResponse
import hotshot, hotshot.stats
import sys, StringIO, os
class ProfileMiddleware():
def __init__(self):
pass
def process_view(self, request, view, *args, **kwargs):
for item in request.META['QUERY_STRING'].split(’&‘):
if item.split(’=‘)[0] == ‘profile‘: # profile in query string
# catch the output, must happen before stats object is created
# see https://bugs.launchpad.net/webpy/+bug/133080 for the details
std_old, std_new = sys.stdout, StringIO.StringIO()
sys.stdout = std_new
# now let’s do some profiling
tmpfile = ‘/tmp/%s‘ % request.COOKIES['sessionid']
prof = hotshot.Profile(tmpfile)
# make a call to the actual view function with the given arguments
response = prof.runcall(view, request, *args[0], *args[1])
prof.close()
# and then statistical reporting
stats = hotshot.stats.load(tmpfile)
stats.strip_dirs()
stats.sort_stats(’time‘)
# do the output
stats.print_stats(1.0)
# restore default output
sys.stdout = std_old
# delete file
os.remove(tmpfile)
return HttpResponse(’<pre\>%s</pre>‘ % std_new.getvalue())
return None
Next, you save this code in the file named middleware/profile.py. In order for middleware to work one must enable it in the settings.py file:
MIDDLEWARE_CLASSES = (
...
'djangocode.middleware.profile.ProfileMiddleware‘,
)
The sample output might look like this:
19743 function calls (19238 primitive calls) in 0.064 CPU seconds Ordered by: internal time ncalls tottime percall cumtime percall filename:lineno(function) 4465 0.007 0.000 0.007 0.000 encoding.py:37(force_unicode) 995 0.006 0.000 0.010 0.000 html.py:30(escape) 8 0.005 0.001 0.041 0.005 defaulttags.py:108(render) 995 0.004 0.000 0.030 0.000 debug.py:85(render) 1006 0.004 0.000 0.014 0.000 functional.py:246(wrapper) 32/1 0.004 0.000 0.049 0.049 __init__.py:764(render) 1027 0.004 0.000 0.004 0.000 safestring.py:89(mark_safe) 1010 0.003 0.000 0.005 0.000 __init__.py:690(_resolve_lookup) 1010 0.002 0.000 0.002 0.000 context.py:38(__getitem__) 1009 0.002 0.000 0.009 0.000 __init__.py:533(resolve) 1020 0.002 0.000 0.007 0.000 __init__.py:672(resolve) 42/3 0.001 0.000 0.005 0.002 __init__.py:254(parse) 1 0.001 0.001 0.064 0.064 pages.py:76(account_statistics) 324 0.001 0.000 0.001 0.000 util.py:39(__getattr__) 1405 0.001 0.000 0.001 0.000 __init__.py:790(render) 1 0.001 0.001 0.004 0.004 pages.py:53(_sql) 317 0.001 0.000 0.001 0.000 cursors.py:320(fetchone) 191 0.001 0.000 0.002 0.000 debug.py:25(create_token) 37 0.001 0.000 0.001 0.000 __init__.py:487(__init__) 3 0.001 0.000 0.002 0.001 debug.py:10(tokenize) 191 0.001 0.000 0.001 0.000 __init__.py:229(create_token) 10 0.001 0.000 0.001 0.000 cursors.py:273(_do_query) 293/76 0.001 0.000 0.001 0.000 __init__.py:750(get_nodes_by_type) 290 0.001 0.000 0.001 0.000 connections.py:189(string_decoder)
Note you should only install the profiling middleware in the development version since you don’t want just anybody to see the structure of your code from live version. And the next time you would like to check why a certain url is running slow just append it ?profile.
