Skip to content
Back to Blog

Faster Django Profiling

Rich Jones

Feb 20, 2017 10:00:00 AM

If you haven't noticed, we've made some serious updates to gun.io!

As our search results are now rendered on the client side rather than on the server, we had to write a whole new API to get the data into the client. Once we had written it, we found that it was far slower than what we considered to be acceptable - results were averaging at 1.7s - and we shoot for sub 200ms response times. Not good! But what was going wrong? Why was Django being so slow? It actually wasn't easy to see immediately, and the normally wonderful Django Debug Toolbar wasn't any use as it doesn't work on AJAX requests.

 

Using a Profiler

What we needed was a way to profile our code through the browser. Much digging around on the internet found a very old snippet of a Django profiling middleware which seemed perfect for the tasks. Unfortunately, it didn't work with modern versions of Django, but I quickly fixed it up and am including it below.

  # Orignal version taken from http://www.djangosnippets.org/snippets/186/
  # Original author: udfalkso
  # Modified by: Shwagroo Team and Gun.io
   
  import sys
  import os
  import re
  import hotshot, hotshot.stats
  import tempfile
  import StringIO
   
  from django.conf import settings
   
  words_re = re.compile( r'\s+' )
   
  group_prefix_re = [
  re.compile( "^.*/django/[^/]+" ),
  re.compile( "^(.*)/[^/]+$" ), # extract module path
  re.compile( ".*" ), # catch strange entries
  ]
   
  class ProfileMiddleware(object):
  """
  Displays hotshot profiling for any view.
  http://yoursite.com/yourview/?prof
   
  Add the "prof" key to query string by appending ?prof (or &prof=)
  and you'll see the profiling results in your browser.
  It's set up to only be available in django's debug mode, is available for superuser otherwise,
  but you really shouldn't add this middleware to any production configuration.
   
  WARNING: It uses hotshot profiler which is not thread safe.
  """
  def process_request(self, request):
  if (settings.DEBUG or request.user.is_superuser) and 'prof' in request.GET:
  self.tmpfile = tempfile.mktemp()
  self.prof = hotshot.Profile(self.tmpfile)
   
  def process_view(self, request, callback, callback_args, callback_kwargs):
  if (settings.DEBUG or request.user.is_superuser) and 'prof' in request.GET:
  return self.prof.runcall(callback, request, *callback_args, **callback_kwargs)
   
  def get_group(self, file):
  for g in group_prefix_re:
  name = g.findall( file )
  if name:
  return name[0]
   
  def get_summary(self, results_dict, sum):
  list = [ (item[1], item[0]) for item in results_dict.items() ]
  list.sort( reverse = True )
  list = list[:40]
   
  res = " tottime\n"
  for item in list:
  res += "%4.1f%% %7.3f %s\n" % ( 100*item[0]/sum if sum else 0, item[0], item[1] )
   
  return res
   
  def summary_for_files(self, stats_str):
  stats_str = stats_str.split("\n")[5:]
   
  mystats = {}
  mygroups = {}
   
  sum = 0
   
  for s in stats_str:
  fields = words_re.split(s);
  if len(fields) == 7:
  time = float(fields[2])
  sum += time
  file = fields[6].split(":")[0]
   
  if not file in mystats:
  mystats[file] = 0
  mystats[file] += time
   
  group = self.get_group(file)
  if not group in mygroups:
  mygroups[ group ] = 0
  mygroups[ group ] += time
   
  return "<pre>" + \
  " ---- By file ----\n\n" + self.get_summary(mystats,sum) + "\n" + \
  " ---- By group ---\n\n" + self.get_summary(mygroups,sum) + \
  "</pre>"
   
  def process_response(self, request, response):
  if (settings.DEBUG or request.user.is_superuser) and 'prof' in request.GET:
  self.prof.close()
   
  out = StringIO.StringIO()
  old_stdout = sys.stdout
  sys.stdout = out
   
  stats = hotshot.stats.load(self.tmpfile)
  stats.sort_stats('time', 'calls')
  stats.print_stats()
   
  sys.stdout = old_stdout
  stats_str = out.getvalue()
   
  if response and response.content and stats_str:
  response.content = "<pre>" + stats_str + "</pre>"
   
  response.content = "\n".join(response.content.split("\n")[:40])
   
  response.content += self.summary_for_files(stats_str)
   
  os.unlink(self.tmpfile)
   
  return response
view raw middleware.py hosted with ❤ by GitHub

 

To use this middleware, save this file in your application as middleware.py. Then, in the MIDDLEWARE_CLASSES of your settings.py, include the line

 

'yourproject.yourapp.middleware.ProfileMiddleware',

(with the 'yourproject' and 'yourapp' changed to your appropriate values, of course.) You will also need to install the 'hotshot' package, so if you don't have that installed already then pip install hotshot.

 

Reading the Output

Now, to use the profiler, simply add the string '?prof' to the end of your URL, and you'll see the profile of that page. Awesome! But.. what does this wall of voodoo mean?

The profiling output is not very intuitive if you haven't seen it before, so let's dive in!

The columns it's showing you are the number of times a function is called, the "total time" that function took, the time per call, the cumulative time of that function, and the ratio of cumulative time to primitive calls. We're interested in 'cumtime', the fourth column. The results aren't sorted, so you'll have to look through the list and see which functions are taking the most time. Anything greater than 0.100 or even .050 could be worth investigating.

If the function has a low per-call time but a high cumulative time, your code is probably spending too much time in a loop - see if you can find a more efficient algorithm, use less nested loops or way to break earlier! The string associated with your problem line may actually not be immediately helpful, but hopefully it will serve as a good starting point for you - if you see many expensive calls to 'sql', it could be your database code, if you see many expensive calls to 'template', it could be your templating code, etcetera etcetera.

In our case, we had forgotten to use a 'selected_related()' on one of our database calls. Now our API is super fast, hooray!

Once you're done, remember to remove the middleware from your settings!

Written By:

Rich Jones

Want to get our totally not sh*tty weekly newsletter?

Sometimes The Wayfarer is funny, sometimes insightful, but always the least spammy newsletter this side of Tatooine.