Django 1.1 Testing and Debugging — Save 50%
Building rigorously tested and bug-free Django applications
In this article by Karen M. Tracey, author of the book Django 1.1 Testing and Debugging, we will see that the Django Debug Toolbar is a very useful general purpose debugging tool for Django applications. It lets you see the SQL queries that were needed to produce a page. We will also see, it goes far beyond that, providing easy access to much more information about the SQL queries and other aspects of request processing.
The debug toolbar has a far more advanced way of displaying the information than simply embedding it in HTML comments. The capabilities are best shown by example, so we will immediately proceed with installing the toolbar.
Installing the Django Debug Toolbar
The toolbar can be found on the Python package index site: http://pypi.python.org/pypi/django-debug-toolbar. Once installed, activating the debug toolbar in a Django project is accomplished with the addition of just a couple of settings.
First, the debug toolbar middleware, debug_toolbar.middleware.DebugToolbarMiddleware, must be added to the MIDDLEWARE_CLASSES setting. The documentation for the toolbar notes that it should be placed after any other middleware that encodes the response content, so it is best to place it last in the middleware sequence.
Second, the debug_toolbar application needs to be added to INSTALLED_APPS. The debug_toolbar application uses Django templates to render its information, thus it needs to be listed in INSTALLED_APPS so that its templates will be found by the application template loader.
Third, the debug toolbar requires that the requesting IP address be listed in INTERNAL_IPS.
Finally, the debug toolbar is displayed only when DEBUG is True. We've been running with debug turned on, so again we don't have to make any changes here. Note also that the debug toolbar allows you to customize under what conditions the debug toolbar is displayed. It's possible, then, to set things up so that the toolbar will be displayed for requesting IP addresses not in INTERNAL_IPS or when debug is not turned on, but for our purposes the default configuration is fine so we will not change anything.
One thing that is not required is for the application itself to use a RequestContext in order for things such as the SQL query information to be available in the toolbar. The debug toolbar runs as middleware, and thus is not dependent on the application using a RequestContext in order for it to generate its information. Thus, the changes made to the survey views to specify RequestContexts on render_to_response calls would not have been needed if we started off first with the Django Debug Toolbar.
Debug toolbar appearance
Once the debug toolbar is added to the middleware and installed applications settings, we can see what it looks like by simply visiting any page in the survey application. Let's start with the home page. The returned page should now look something like this:
Note this screenshot shows the appearance of the 0.8.0 version of the debug toolbar. Earlier versions looked considerably different, so if your results do not look like this you may be using a different version than 0.8.0. The version that you have will most likely be newer than what was available when this was written, and there may be additional toolbar panels or functions that are not covered here.
As you can see, the debug toolbar appears on the right-hand side of the browser window. It consists of a series of panels that can be individually enabled or disabled by changing the toolbar configuration. The ones shown here are the ones that are enabled by default.
Before taking a closer look at some of the individual panels, notice that the toolbar contains an option to hide it at the top. If Hide is selected, the toolbar reduces itself to a small tab-like indication to show that it is present:
This can be very useful for cases where the expanded version of the toolbar obscures application content on the page. All of the information provided by the toolbar is still accessible, after clicking again on the DjDT tab; it is just out of the way for the moment.
Most of the panels will provide detailed information when they are clicked. A few also provide summary information in the main toolbar display. As of debug toolbar version 0.8.0, the first panel listed, Django Version, only provides summary information. There is no more detailed information available by clicking on it. As you can see in the screenshot, Django 1.1.1 is the version in use here.
Note that the current latest source version of the debug toolbar already provides more information for this panel than the 0.8.0 release. Since 0.8.0, this panel has been renamed to Versions, and can be clicked to provide more details. These additional details include version information for the toolbar itself and for any other installed Django applications that provide version information.
The other three panels that show summary information are the Time, SQL, and Logging panels. Thus, we can see at a glance from the first appearance of the page that 60 milliseconds of CPU time were used to produce this page (111 milliseconds total elapsed time), that the page required four queries, which took 1.95 milliseconds, and that zero messages were logged during the request.
In the following sections, we will dig into exactly what information is provided by each of the panels when clicked. We'll start first with the SQL panel, since it is one of the most interesting and provides the same information (in addition to a lot more).
The SQL panel
If we click on the SQL section of the debug toolbar, the page will change to:
At a glance, this is a much nicer display of the SQL queries for the page than what we came up with earlier. The queries themselves are highlighted so that SQL keywords stand out, making them easier to read. Also, since they are not embedded inside an HTML comment, their content does not need to be altered in any way—there was no need to change the content of the query containing the double dash in order to avoid it causing display problems. (Now would probably be a good time to remove that added query, before we forget why we added it.)
Notice also that the times listed for each query are more specific than what was available in Django's default query history. The debug toolbar replaces Django's query recording with its own, and provides timings in units of milliseconds instead of seconds.
The display also includes a graphical representation of how long each query took, in the form of horizontal bars that appear above each query. This representation makes it easy to see when there are one or more queries that are much more expensive than the others. In fact, if a query takes an excessive amount of time, its bar will be colored red. In this case, there is not a great deal of difference in the query times, and none took particularly long, so all the bars are of similar length, and are colored gray.
Digging deeper, some of the information we had to manually figure out earlier in this article is just a click away on this SQL query display. Specifically, the answer to the question of what line of our code triggered a particular SQL query to be issued. Each of the displayed queries has a Toggle Stacktrace option, which when clicked will show the stack trace associated with the query:
Here we can see that all queries are made by the home method in the survey views. py file. Note that the toolbar filters out levels in the stack trace that are within Django itself, which explains why each of these has only one level shown. The first query is triggered by Line 61, which contains the filter call added to test what will happen if a query containing two dashes in a row was logged. The remaining queries are all attributed to Line 66, which is the last line of the render_to_response call in the home view. These queries, as we figured out earlier, are all made during the rendering of the template. (Your line numbers may vary from those shown here, depending on where in the file various functions were placed.)
Finally, this SQL query display makes available information that we had not even gotten around to wanting yet. Under the Action column are links to SELECT, EXPLAIN, and PROFILE each query. Clicking on the SELECT link shows what the database returns when the query is actually executed. For example:
Similarly, clicking on EXPLAIN and PROFILE displays what the database reports when asked to explain or profile the selected query, respectively. The exact display, and how to interpret the results, will differ from database to database. (In fact, the PROFILE option is not available with all databases—it happens to be supported by the database in use here, MySQL.) Interpreting the results from EXPLAIN and PROFILE is beyond the scope of what's covered here, but it is useful to know that if you ever need to dig deep into the performance characteristics of a query, the debug toolbar makes it easy to do so.
We've now gotten a couple of pages deep into the SQL query display. How do we get back to the actual application page? Clicking on the circled >> at the upper-right of the main page display will return to the previous SQL query page, and the circled >> will turn into a circled X. Clicking the circled X on any panel detail page closes the details and returns to displaying the application data. Alternatively, clicking again on the panel area on the toolbar for the currently displayed panel will have the same effect as clicking on the circled symbol in the display area. Finally, if you prefer using the keyboard to the mouse, pressing Esc has the same effect as clicking the circled symbol.
Now that we have completely explored the SQL panel, let's take a brief look at each of the other panels provided by the debug toolbar.
The Time panel
Clicking on the Time panel brings up more detailed information on where time was spent during production of the page:
The total CPU time is split between user and system time, the total elapsed (wall clock) time is listed, and the number of voluntary and involuntary context switches are displayed. For a page that is taking too long to generate, these additional details about where the time is being spent can help point towards a cause.
Note that the detailed information provided by this panel comes from the Python resource module. This is a Unix-specific Python module that is not available on non-Unix-type systems. Thus on Windows, for example, the debug toolbar time panel will only show summary information, and no further details will be available.
|Building rigorously tested and bug-free Django applications|
eBook Price: $29.99
Book Price: $49.99
The Settings panel
Clicking on Settings brings up a scrollable display of all the settings in effect. The code used to create this display is identical to the code used to display the settings on a Django debug page, so the display here will be identical to what you would see on a debug page.
The HTTP Headers panel
Clicking on HTTP Headers brings up a display of all the HTTP headers for the request:
This is a subset of the information available in the META section of a debug page. The request.META dictionary contains all of the HTTP headers for a request in addition to other information that has nothing to do with the request, since request.META is initially copied from the os.environ dictionary. The debug toolbar has chosen to filter the displayed information to include only information pertinent to the HTTP request, as shown in the screenshot.
The Request Vars panel
Clicking on Request Vars brings up a display of cookies, session variables, GET variables, and POST data for the request. Since the survey application home page doesn't have any information to display for any of those, the Request Vars display for it is not very interesting. Instead, here is an example from the admin application, which does use a session, and so it actually has something to display:
Here you can see the sessionid cookie that was set as a result of the admin application using the django.contrib.sessions application, and you can also see the individual session variables that have been set in the session.
The Templates panel
Clicking on Templates brings up a display of information about template processing for the request. Returning to the survey home page as an example:
The Template paths section lists the paths specified in the TEMPLATE_DIRS setting; since we have not added anything to that setting, it is empty.
The Templates section shows all of the templates rendered for the response. Each template is listed, showing the name specified by the application for rendering first. Clicking on this name will bring up a display of the actual template file contents. Under the application-specified name is the full file path for the template. Finally, each template also has a Toggle Context link that can be used to see the details of the context used by each of the rendered templates.
The Context processors section shows all of the installed context processors. Under each is a Toggle Context link that when clicked will show the context variables that the associated context processor adds to the context.
Note that the context processors are listed regardless of whether the application used a RequestContext to render the response. Thus, their being listed on this page does not imply that the variables they set were added to the context for this particular response.
The Signals panel
Clicking on Signals brings up a display of the signal configuration:
All of the defined Django signals are listed. For each, the arguments provided are shown along with the receivers that have been connected to the signal.
Note that this display does not indicate anything about what signals were actually triggered during the production of the current page. It simply shows how the signals are configured.
The Logging panel
Finally, the Logging panel shows any messages sent via Python's logging module during the course of the request processing. Since we have not yet investigated using logging in the survey application, and since as of Django 1.1, Django itself does not use the Python logging module, there is nothing for us to see on this panel yet.
Redirect handling by the debug toolbar
Now recall the reason we started investigating the debug toolbar: we found that our original approach to tracking SQL queries for a page did not work for pages that returned an HTTP redirect instead of rendering a template. How does the debug toolbar handle this better? To see this, click on the Television Trends link on the home page, select answers for the two questions, and press Submit. The result will be:
This page shows an example of why it is sometimes necessary to use the Hide option on the toolbar, since the toolbar itself obscures part of the message on the page. Hiding the toolbar shows that the full message is:
The Django Debug Toolbar has intercepted a redirect to the above URL for debug viewing purposes. You can click the above link to continue with the redirect as normal. If you'd like to disable this feature, set the DEBUG_TOOLBAR_CONFIG dictionary's key INTERCEPT_REDIRECTS to False.
What the debug toolbar has done here is intercepted the redirect request and replaced it with a rendered response containing a link to the location specified in the original redirect. The toolbar itself is still in place and available to investigate whatever information we might like to see about the processing of the request that generated the redirect. For example, we can click on the SQL section and see:
These are the SQL queries that were needed to process the inbound posted form. Not surprisingly, the first four are exactly the same as what we saw for generating the form in the first place, since the same code path is initially followed for both GET and POST requests.
It is only after those queries are issued that the display_active_survey view has different code paths for GET and POST. Specifically, in the case of a POST, the code is:
if request.method == 'POST':
chosen_answers = 
for qf in qforms:
if not qf.is_valid():
for answer in chosen_answers:
answer.votes += 1
The fifth and sixth queries listed on this page are retrieving the specific answer instances that were selected on the submitted form. Unlike the GET case, where all answers for a given question were being retrieved in the fifth and sixth queries, these queries specify an answer id in the SQL WHERE clause as well as a question id. In the POST case, it is not necessary to retrieve all answers for a question; it is sufficient to retrieve only the one that was chosen.
Toggling the stack trace for these queries shows that they are resulting from the if not qf.is_valid() line of code. This makes sense, since in addition to validating the input, the is_valid method normalizes the posted data before placing it in the form's cleaned_data attribute. In the case of a ModelChoiceField, the normalized value is the chosen model object instance, so it is necessary for the validation code to retrieve the chosen object from the database.
After both submitted forms are found to be valid, the else leg of this code runs. Here, the vote count for each chosen answer is incremented, and the updated answer instance is saved to the database. This code, then, must be responsible for the final four queries previously shown. This can be confirmed by checking the stack trace for those four queries: all point to the answer.save() line of code.
But why are four SQL statements, two SELECT and two UPDATE, needed to save two answers to the database? The UPDATE statements are self-explanatory, but the SELECT statements that precede them are a bit curious. In each case, the constant 1 is selected from the survey_answer table with a WHERE clause specifying a primary key value that matches the survey that is in the process of being saved. What is the intent of this query?
What the Django code is doing here is attempting to determine if the answer being saved already exists in the database or if it is new. Django can tell by whether any results are returned from the SELECT if it needs to use an UPDATE or an INSERT when saving the model instance to the database. Selecting the constant value is more efficient than actually retrieving the result when the only information needed is whether the result exists.
You might think the Django code should know, just based on the fact that the primary key value is already set for the model instance, that the instance refl ects data that is already in the database. However, Django models can use manually-assigned primary key values, so the fact that the primary key value has been assigned does not guarantee the model has already been saved to the database. Therefore, there is an extra SELECT to determine the model status before saving the data.
The survey application code, though, certainly knows that all of the answer instances it is saving when processing a survey response are already saved in the database. When saving, the survey code can indicate that the instance must be saved via an UPDATE and not an INSERT by specifying force_update on the save call:
If we make that change and try submitting another survey, we see that the SELECT queries have been eliminated from processing for this case, reducing the total number of queries needed from 10 to 8:
(Yes, I realize that earlier I said now was not the time for making optimizations, yet here I went ahead and made one. This one was just too easy to pass up.)
We have now covered all of the panels displayed by default by the Django Debug Toolbar, and seen how its default handling of returned redirects allows investigation of the processing that led up to the redirect. It is a very fl exible tool: it supports adding panels, changing what panels are displayed, changing when the toolbar is displayed, and configuration of various other options. Discussing all of this is beyond the scope of what is covered here. Hopefully what has been covered gives you a taste for the power of this tool. If you are interested in learning more details on how to configure it, the README linked from its home page is a good place to start.
If you have read this article you may be interested to view :
- Handling Invalid Survey Submissions with Django
- Tracking SQL Queries for a Request using Django
- Django Debugging Overview
|Building rigorously tested and bug-free Django applications|
eBook Price: $29.99
Book Price: $49.99
About the Author :
Karen has a PhD in Electrical/Computer Engineering from the University of Notre Dame. Her research there focused on distributed operating systems, which led to work in industry centered on communications protocols and middleware. Outside of work she has an interest in puzzles, which led her to take up crossword construction. She has published nearly 100 puzzles in The New York Times, The Los Angeles Times syndicate, The New York Sun, and USA Today. She amassed a database of thousands of puzzles to aid in constructing and cluing her own puzzles. The desire to put a web frontend on this database is what led her to Django. She was impressed by the framework and its community, and became an active core framework contributor. Karen is one of the most prolific posters on the Django users mailing list. Her experience in helping hundreds of people there guided her in choosing the best and most useful material to include in this book.