Profiling Django
At the recent WebDev offsite in Portland, we had a chance to spend the day working on any project we wanted and then show the results off that afternoon. I chose to play around with Socket IO. This is also inspired by a great talk by Alexander Bourget at Confoo.
A while back I was trying to profile my Django site and find some speed improvements. I started off by looking for a nice way to profile a Django site and give me some output. That's easy, as it turns out there's some code in Django command extensions that outputs profiles:
python manage.py runprofileserver --use-cprofile --prof-path=/tmp/output
For each request to your Django site this will output in cprofile format a profile of the request, one per file. Now we just need a tool to read it.
When Googling this the main blog posts I found covered a format called kcachegrind, which is used by a tool to output some useful information. Unfortunately on a Mac this means using X Windows, Mac ports and a whole pile of stuff. There's MacCallGrind, but that didn't work, just hung. So that's where I started writing something.
Talisker is a Socket IO based server using gevent and Pyramid. It's a stand alone Pyramid app that you can start up and then open in your browser. It will scan a directory and collect all profiles in that directory ready to send back to the client when messages come in. So we get something like this:
You can see a nice graph of the directories. Since this is Socket IO and using Flot, it will update automatically and show you time the requests took in real time. Woo.
Because it's using cprofile, we can parse the profiles with the Python pstats module. Which awesomely has this line in it:
# Class for printing reports on profiled python code. rev 1.0 4/1/94
From 1994, that's some vintage. Pstats has the nice ability to group multiple profiles together, so we can group together all the requests to /random on my Django site and get some stats for all the pages. Because this is just a table, I added a JS table sorted on to that. Being able to sort the stats is nice too:
You could also view each request individually if you wanted to see just one slow request. This will let you home in on an element like this:
And then clicking on that will give you the line of the source:
And sure enough you can see the problem.
Previously I'd found the output of the runprofileserver simple and useful. So I'd decided to write a Nose plugin. Talisker Nose is a plugin that you can run whilst running your unit tests and it will output to the same file format and can be parsed by Talisker. Sadly, this kind of ruins the graph display. But it can be useful for finding what happens in the tests.
This is of course an app written quickly, chances are if you try it, it won't work. But it's something that I didn't find a nice solution for in the Python world and something that I would like to improve without resorting to the old fashioned native apps. There's no need for that anymore. Or perhaps Tarek will write it for us.