In this post, I'll discuss profiling Django applications through a case study in linkrdr's code. Through the use of profiling tools, I was able to reduce the number of database queries a view was using from 1300 to 2.
Introduction To Profiling
At some point in most Django projects, some part of the application becomes 'slow'. This doesn't have to be the case (more on that later), but it's often the result of changes made without performance in mind.
In the beginning, this is actually a good thing: focus on making it work first, then focus on making it fast. Of course, you don't want to code yourself into a corner by writing code that "works" but does so in a way that it will never be fast. Instead, you want to keep performance in the back of your mind while implementing a solution that makes sense.
Once you've proven your solution works through your automated tests (You are using automated tests, right?), the next step is to make sure its performance is acceptable. Note that I didn't say 'optimal'. Don't waste time making something faster than it needs to be. This should be common sense but, once the optimization bug bites, it's common for developers to go a bit off the deep end and keep trying to find optimizations long after it's necessary.
So you're solution works, but it's slower than what you've deemed acceptable. What's the first step? For far too many developers, it's
- Fire up my editor
- Take a look around
- Guess what I think is causing slowness
- Make a bunch of changes
- Hope it got faster
Wrong, wrong, wrong. If you take away one thing from the post, let this be it: developers are notoriously bad at predicting performance bottlenecks. People think, 'Well, I wrote it, so I should know what could be causing slowness.' Instead of relying on faulty intuition, we should be relying on data.
Profiling is the process by which we accumulate data on the performance of an application. This data can come in many forms, but usually is some variation on reporting two things: the number of times a function or line of code was executed and how much time it took to do so. For every modern language there exist some form of profiling tools. Use them.
A Case Study
linkrdr allows, among other things, a user to
import their RSS/Atom/Twitter/Anything Else feeds and get an
intelligently laid out view of the links contained in their feeds. The
show_items view for linkrdr is responsible for retrieving the user's
current feeds, gathering the links from those feeds' entries, and
scoring, sorting, and aggregating the links for presentation.
When I first began work on the view, I did so with a unit test pre-written. I needed to get that test working, so I did so in the simplest way possible. Here's what the code looked like:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18
Simple, right? If someone asked you to write pseudo-code to perform this task, I'm guessing it would look largely similar to this. Remember, that's a good thing in the beginning. We're focusing on correctness more than performance.
This code turned out to be 'all right' in the performance department. It eventually got on my nerves, though, because I knew it has a problem that experienced Django developers probably spotted right away. Even though I was %99.99 percent sure I knew what was slowing down this view, I approached optimizing this code the same way I approach any optimization task. I began with profiling.
Profiling in Django is a little all over the map. There isn't really a
universally accepted solution, as you can tell by reading the
Django wiki. I've
for a while now, and it has a very nice profiling feature:
manage.py runprofileserver. It starts the Django webserver with the (now unmaintained but still useful) hotshot profiler and writes a .prof profiling results file on every request.
So I fired up the profile server and navigated to my view. A .prof file was added to my /tmp directory. To interpret it, I entered the Django shell and did the following:
1 2 3 4 5 6
The result of this was as I expected:
In : stats.print_stats(20) 557944 function calls (485997 primitive calls) in 3.959 seconds Ordered by: internal time, call count List reduced from 457 to 20 due to restriction <20> ncalls tottime percall cumtime percall filename:lineno(function) 1310 0.763 0.001 0.783 0.001 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/db/backends/postgresql_psycopg2/base.py:42(execute) 68656/15272 0.485 0.000 1.099 0.000 /usr/lib/python2.7/copy.py:145(deepcopy) 67792 0.173 0.000 0.173 0.000 /usr/lib/python2.7/copy.py:267(_keep_alive) 1310 0.152 0.000 0.155 0.000 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/db/backends/postgresql_psycopg2/base.py:116(_cursor) 3818 0.136 0.000 1.294 0.000 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/db/models/sql/query.py:223(clone) 10041/5020 0.109 0.000 0.544 0.000 /usr/lib/python2.7/copy.py:234(_deepcopy_tuple) 2344 0.089 0.000 0.106 0.000 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/db/models/base.py:275(__init__) 8838/7636 0.076 0.000 0.575 0.000 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/utils/tree.py:55(__deepcopy__) 10258 0.067 0.000 0.072 0.000 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/utils/datastructures.py:110(__init__) 1310 0.057 0.000 0.111 0.000 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/db/models/sql/compiler.py:218(get_default_columns) 3654 0.053 0.000 1.816 0.000 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/db/models/query.py:214(iterator) 3280 0.050 0.000 2.209 0.001 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/db/models/fields/related.py:288(__get__) 21494/19090 0.046 0.000 0.356 0.000 /usr/lib/python2.7/copy.py:226(_deepcopy_list) 5021 0.045 0.000 0.326 0.000 /usr/lib/python2.7/copy.py:306(_reconstruct) 1310 0.044 0.000 0.420 0.000 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/db/models/sql/compiler.py:47(as_sql) 1310 0.040 0.000 0.069 0.000 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/db/models/sql/query.py:99(__init__) 2620 0.037 0.000 0.099 0.000 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/db/models/sql/compiler.py:749(<lambda>) 1310 0.037 0.000 0.846 0.001 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/db/backends/util.py:31(execute) 3818 0.037 0.000 1.345 0.000 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/db/models/query.py:751(_clone) 10258 0.037 0.000 0.037 0.000 /home/illest/linkrdr/virtualenv/local/lib/python2.7/site-packages/django/utils/datastructures.py:105(__new__)
As you can see, psycopg2 is calling
execute 1310 times, which is
causing all sorts of slowness. Execute, in case you didn't guess, is the
function that executes an SQL query against the database. My view was
making 1310 database queries for a user with 4 feeds.
Well, now we know what the cause of the slowness is. The question is: how do we fix it? I began by activating the django-debug-toolbar, which lets you view the number of SQL queries a page generates, among many other useful things. I confirmed that the number of queries reported was the same in the debug-toolbar and went about optimizing the code.
The first approach to optimization in Django should always be to modify the problematic function without changing anything else. Sometimes, you won't be able to optimize without making changes to your models or other parts of your application, but this kind of change shouldn't be your first inclination.
So I went back to my view and asked: is there a better way to get the same
data I'm currently getting? It turns out there is: using
select_related in my query.
select_related populates your QuerySet with the records you requested
plus related records based on ForeignKeys in your model. If I could
change my query to use select related, I could drastically reduce the
number of queries the view required.
There was an issue, though. My models were set up so that a Link
belonged to an Entry, which belonged to a Feed, which had a set of
Users associated. I had gone from the top down: a query filtering feeds
that belonged to the current user. What I needed to do to realize the
select_related was to get all of the objects I needed in
one query. Since what I really needed was
Link objects, I changed the
This would give me all of the links that I was interested in, plus all
of the related objects that I'd be using. I reran the view profiling and
saw something unexpected: I was still performing over 600 queries. Using
the debug-toolbar to determine the lines of code generating these
queries quickly revealed my error. When using
select_related, you must
make sure to reuse the QuerySet in subsequent code. If you
accidentally use a new QuerySet (even if the objects would have been in
the original QuerySet) it will result in a new database query. This
cascades down to any other objects using the new QuerySet, and now you've
got the same issue again.
After making sure I reused the QuerySet throughout my view and the
functions it called, I reran the view using the debug-toolbar. Finally I
had the results I wanted: all of the data generated in just 2 queries
(the other query was the User's Session query, which can't really be
avoided). One thing you need to be aware of when using
is that the query can get so large as to be slower than the iterative
approach. That's something I'll definitely need to keep an eye on in the
After re-running the tests to confirm my new code worked as expected and committing the code to git, I had one more task left: update my unit tests to reflect my new changes. While I didn't make any functional changes, I did make performance changes, and performance changes should be unit tested just like functionality changes.
TestCase class has an assertion
that checks the number of queries performed during a test. I simply
added this assertion the my view test and I was done. This prevents me
from adding code in the future that increases the number of database
queries without forcing myself to decide if that's acceptable.
Questions or comments on Profiling Django Applications? Let me know in the comments below. Also, follow me on Twitter to see all of my blog posts and updates.Posted on by Jeff Knupp