Tracking SQL Queries for a Request using Django

Exclusive offer: get 50% off this eBook here
Django 1.1 Testing and Debugging

Django 1.1 Testing and Debugging — Save 50%

Building rigorously tested and bug-free Django applications

$29.99    $15.00
by Karen M. Tracey | April 2010 | Content Management Open Source Web Development

Packt is due to launch a new Open Source brand, into which future VirtualBox titles will be published. For more information on that launch, look here

In this article by Karen M. Tracey, author of the book Django 1.1 Testing and Debugging, we will develop a template code that can be used to include information about all of the SQL queries needed to render a page in the page itself.

For a typical Django application, database interactions are of key importance. Ensuring that the database queries being made are correct helps to ensure that the application results are correct. Further, ensuring that the database queries produced for the application are efficient helps to make sure that the application will be able to support the desired number of concurrent users.

Django provides support in this area by making the database query history available for examination. This type of access is useful to see the SQL that is issued as a result of calling a particular model method. However, it is not helpful in learning about the bigger picture of what SQL queries are made during the processing of a particular request.

This section will show how to include information about the SQL queries needed for production of a page in the page itself. We will alter our existing survey application templates to include query information, and examine the query history for some of the existing survey application views. Though we are not aware of any problems with the existing views, we may learn something in the process of verifying that they issue the queries we expect.

Settings for accessing query history in templates

Before the query history can be accessed from a template, we need to ensure some required settings are configured properly. Three settings are needed in order for the SQL query information to be available in a template. First, the debug context processor, django.core.context_processors.debug, must be included in the TEMPLATE_CONTEXT_PROCESSORS setting. This context processor is included in the default value for TEMPLATE_CONTEXT_PROCESSORS. We have not changed that setting; therefore we do not need to do anything to enable this context processor in our project.

Second, the IP address of the machine sending the request must be listed in the INTERNAL_IPS setting. This is not a setting we have used before, and it is empty by default, so we will need to add it to the settings file. When testing using the same machine as where the development server runs, setting INTERNAL_IPS to include the loopback address is sufficient:

# Addresses for internal machines that can see potentially sensitive
# information such as the query history for a request.
INTERNAL_IPS = ('127.0.0.1', )

If you also test from other machines, you will need to include their IP addresses in this setting as well.

Third and finally, DEBUG must be True in order for the SQL query history to be available in templates.

When those three settings conditions are met, the SQL query history may be available in templates via a template variable named sql_queries. This variable contains a list of dictionaries. Each dictionary contains two keys: sql and time. The value for sql is the SQL query itself, and the value for time is the number of seconds the query took to execute.

Note that the sql_queries context variable is set by the debug context processor. Context processors are only called during template rendering when a RequestContext is used to render the template. Up until now, we have not used RequestContexts in our survey application views, since they were not necessary for the code so far. But in order to access the query history from the template, we will need to start using RequestContexts. Therefore, in addition to modifying the templates, we will need to change the view code slightly in order to include query history in the generated pages for the survey application.

SQL queries for the home page

Let's start by seeing what queries are issued in order to generate the survey application home page. Recall that the home page view code is:

def home(request):
today = datetime.date.today()
active = Survey.objects.active()
completed = Survey.objects.completed().filter(closes__gte=today-
datetime.timedelta(14))
upcoming = Survey.objects.upcoming().filter(
opens__lte=today+datetime.timedelta(7))
return render_to_response('survey/home.html',
{'active_surveys': active,
'completed_surveys': completed,
'upcoming_surveys': upcoming,
})

There are three QuerySets rendered in the template, so we would expect to see that this view generates three SQL queries. In order to check that, we must first change the view to use a RequestContext:

from django.template import RequestContext
def home(request):
today = datetime.date.today()
active = Survey.objects.active()
completed = Survey.objects.completed().filter(closes__gte=today-
datetime.timedelta(14))
upcoming = Survey.objects.upcoming().filter(
opens__lte=today+datetime.timedelta(7))
return render_to_response('survey/home.html',
{'active_surveys': active,
'completed_surveys': completed,
'upcoming_surveys': upcoming,},
RequestContext(request))

The only change here is to add the RequestContext(request) as a third parameter to render_to_response, after adding an import for it earlier in the file. When we make this change, we may as well also change the render_to_response lines for the other views to use RequestContexts as well. That way when we get to the point of examining the SQL queries for each, we will not get tripped up by having forgotten to make this small change.

Second, we'll need to display the information from sql_queries somewhere in our survey/home.html template. But where? We don't necessarily want this information displayed in the browser along with the genuine application data, since that could get confusing. One way to include it in the response but not have it be automatically visible on the browser page is to put it in an HTML comment. Then the browser will not display it on the page, but it can be seen by viewing the HTML source for the displayed page.

As a first attempt at implementing this, we might change the top of survey/home.html to look like this:

{% extends "survey/base.html" %}
{% block content %}
<!--
{{ sql_queries|length }} queries
{% for qdict in sql_queries %}
{{ qdict.sql }} ({{ qdict.time }} seconds)
{% endfor %}
-->

This template code prints out the contents of sql_queries within an HTML comment at the very beginning of the content block supplied by survey/home. html. First, the number of queries is noted by filtering the list through the length filter. Then the code iterates through each dictionary in the sql_queries list and displays sql, followed by a note in parentheses about the time taken for each query.

How well does that work? If we try it out by retrieving the survey home page (after ensuring the development server is running), and use the browser's menu item for viewing the HTML source for the page, we might see that the comment block contains something like:

<!--
1 queries

SELECT `django_session`.`session_key`, `django_session`.`session_data`,
`django_session`.`expire_date` FROM `django_session` WHERE (`django_
session`.`session_key` = d538f13c423c2fe1e7f8d8147b0f6887 AND `django_
session`.`expire_date` &gt; 2009-10-24 17:24:49 ) (0.001 seconds)

-->

Note that the exact number of queries displayed here will depend on the version of Django you are running. This result is from Django 1.1.1; later versions of Django may not show any queries displayed here. Furthermore, the history of the browser's interaction with the site will affect the queries issued. This result is from a browser that had been used to access the admin application, and the last interaction with the admin application was to log out. You may see additional queries if the browser had been used to access the admin application but the user had not logged out. Finally, the database in use can also affect the specific queries issued and their exact formatting. This result is from a MySQL database.

That's not exactly what we expected. First, a minor annoyance, but 1 queries is wrong, it should be 1 query. Perhaps that wouldn't annoy you, particularly just in internal or debug information, but it would annoy me. I would change the template code that displays the query count to use correct pluralization:

{% with sql_queries|length as qcount %}
{{ qcount }} quer{{ qcount|pluralize:"y,ies" }}
{% endwith %}

Here, since the template needs to use the length result multiple times, it is first cached in the qcount variable by using a {% with %} block. Then it is displayed, and it is used as the variable input to the pluralize filter that will put the correct letters on the end of quer depending on the qcount value. Now the comment block will show 0 queries, 1 query, 2 queries, and so on.

With that minor annoyance out of the way, we can concentrate on the next, larger, issue, which is that the displayed query is not a query we were expecting. Furthermore, the three queries we were expecting, to retrieve the lists of completed, active, and upcoming surveys, are nowhere to be seen. What's going on? We'll take each of these in turn.

The query that is shown is accessing the django_session table. This table is used by the django.contrib.sessions application. Even though the survey application does not use this application, it is listed in our INSTALLED_APPS, since it is included in the settings.py file that startproject generates. Also, the middleware that the sessions application uses is listed in MIDDLEWARE_CLASSES.

The sessions application stores the session identifier in a cookie, named sessionid by default, that is sent to the browser as soon as any application uses a session. The browser will return the cookie in all requests to the same server. If the cookie is present in a request, the session middleware will use it to retrieve the session data. This is the query we see previously listed: the session middleware is retrieving the data for the session identified by the session cookie sent by the browser.

But the survey application does not use sessions, so how did the browser get a session cookie in the first place? The answer is that the admin application uses sessions, and this browser had previously been used to access the admin application. At that time, the sessionid cookie was set in a response, and the browser faithfully returns it on all subsequent requests. Thus, it seems likely that this django_session table query is due to a sessionid cookie set as a side-effect of using the admin application.

Can we confirm that? If we find and delete the cookie from the browser and reload the page, we should see that this SQL query is no longer listed. Without the cookie in the request, whatever code was triggering access to the session data won't have anything to look up. And since the survey application does not use sessions, none of its responses should include a new session cookie, which would cause subsequent requests to include a session lookup. Is this reasoning correct? If we try it, we will see that the comment block changes to:

<!--

0 queries

-->

Thus, we seem to have confirmed, to some extent, what happened to cause a django_session table query during processing of a survey application response. We did not track down what exact code accessed the session identified by the cookie—it could have been middleware or a context processor, but we probably don't need to know the details. It's enough to keep in mind that there are other applications running in our project besides the one we are working on, and they may cause database interactions independent of our own code. If we observe behavior which looks like it might cause a problem for our code, we can investigate further, but for this particular case we will just avoid using the admin application for now, as we would like to focus attention on the queries our own code is generating.

Now that we understand the query that was listed, what about the expected ones that were not listed? The missing queries are due to a combination of the lazy evaluation property of QuerySets and the exact placement of the comment block that lists the contents of sql_queries. We put the comment block at the top of the content block in the home page, to make it easy to find the SQL query information when looking at the page source. The template is rendered after the three QuerySets are created by the view, so it might seem that the comment placed at the top should show the SQL queries for the three QuerySets.

However, QuerySets are lazy; simply creating a QuerySet does not immediately cause interaction with the database. Rather, sending the SQL to the database is delayed until the QuerySet results are actually accessed. For the survey home page, that does not happen until the parts of the template that loop through each QuerySet are rendered. Those parts are all below where we placed the sql_queries information, so the corresponding SQL queries had not yet been issued. The fix for this is to move the placement of the comment block to the very bottom of the content block.

When we do that we should also fix two other issues with the query display. First, notice that the query displayed above has &gt; shown instead of the > symbol that would actually have been in the query sent to the database. Furthermore, if the database in use is one (such as PostgreSQL) that uses straight quotes instead of back quotes for quoting, all of the back quotes in the query would be shown as &quot;. This is due to Django's automatic escaping of HTML markup characters. This is unnecessary and hard to read in our HTML comment, so we can suppress it by sending the sql query value through the safe filter.

Second, the query is very long. In order to avoid needing to scroll to the right in order to see the entire query, we can also filter the sql value through wordwrap to introduce some line breaks and make the output more readable.

To make these changes, remove the added comment block from the top of the content block in the survey/home.html template and instead change the bottom of this template to be:

{% endif %}
<!--
{% with sql_queries|length as qcount %}
{{ qcount }} quer{{ qcount|pluralize:"y,ies" }}
{% endwith %}
{% for qdict in sql_queries %}
{{ qdict.sql|safe|wordwrap:60 }} ({{ qdict.time }} seconds)
{% endfor %}
-->
{% endblock content %}

Now, if we again reload the survey home page and view the source for the returned page, we will see the queries listed in a comment at the bottom:

<!--

3 queries


SELECT `survey_survey`.`id`, `survey_survey`.`title`,
`survey_survey`.`opens`, `survey_survey`.`closes` FROM
`survey_survey` WHERE (`survey_survey`.`opens` <= 2009-10-25
AND `survey_survey`.`closes` >= 2009-10-25 ) (0.000 seconds)

SELECT `survey_survey`.`id`, `survey_survey`.`title`,
`survey_survey`.`opens`, `survey_survey`.`closes` FROM
`survey_survey` WHERE (`survey_survey`.`closes` < 2009-10-25
AND `survey_survey`.`closes` >= 2009-10-11 ) (0.000 seconds)

SELECT `survey_survey`.`id`, `survey_survey`.`title`,
`survey_survey`.`opens`, `survey_survey`.`closes` FROM
`survey_survey` WHERE (`survey_survey`.`opens` > 2009-10-25
AND `survey_survey`.`opens` <= 2009-11-01 ) (0.000 seconds)

-->

That is good, those look like exactly what we expect to see for queries for the home page. Now that we seem to have some working template code to show queries, we will consider packaging up this snippet so that it can easily be reused elsewhere.

Django 1.1 Testing and Debugging Building rigorously tested and bug-free Django applications
Published: April 2010
eBook Price: $29.99
Book Price: $49.99
See more
Select your format and quantity:

Packaging the template query display for reuse

We've now got a small block of template code that we can put in any template to easily see what SQL queries were needed to produce a page. However, it is not so small that it can be easily re-typed whenever it might come in handy. Therefore, it would be good to package it up in a form where it can be conveniently included wherever and whenever it might be needed. The Django template {% include %} tag makes this easy to do.

Where should the snippet go? Note that this template snippet is completely general and not in any way tied to the survey application. While it would be easy to simply include it among the survey templates, putting it there will make it harder to reuse for future projects. A better approach is to put it in an independent application.

Creating an entirely new application just for this one snippet may seem a bit extreme. However, it is common during development to create small utility functions or template snippets that don't really belong in the main application. So it is likely during development of a real project that there would be other such things that should logically be placed somewhere besides the main application. It's helpful to have someplace else to put them.

Let's create a new Django application, then, to hold any general utility code that does not logically belong within the survey application:

kmt@lbox:/dj_projects/marketr$ python manage.py startapp gen_utils

Since its purpose is to hold general utility code, we've named the new application gen_utils. It can serve as a place to put any non-survey-specific code that seems like it might be potentially re-usable elsewhere. Note that as time goes on and more and more stuff accumulates in an application like this, it may become apparent that some subset of it would be useful to package into its own independent, self-contained application with a more descriptive name than gen_utils. But for now it is enough to start with one place to put utility code that is not really tied to the survey application.

Next, we can create a templates directory within gen_utils, and a gen_utils directory under templates, and create a file, showqueries.html, to hold the template snippet:

{% if sql_queries %}<!--
{% with sql_queries|length as qcount %}
{{ qcount }} quer{{ qcount|pluralize:"y,ies" }}
{% endwith %}
{% for qdict in sql_queries %}
{{ qdict.sql|safe|wordwrap:60 }} ({{ qdict.time }} seconds)
{% endfor %}
-->{% endif %}

We've made one change here from the previous code placed directly in the survey/home.html template, which is to place the entire HTML comment block inside an {% if sql_qureies %} block. If the sql_queries variable has not been included in the template context, then there is no reason to produce the comment at all.

As part of packaging code for reuse, it's also good practice to double-check and make sure that the code is truly reusable and not going to fail in odd ways if given unexpected or unusual input. Taking a look at that snippet, is there anything that might be found in an arbitrary sql_queries input that could cause a problem?

The answer is yes. If a SQL query value contains the HTML end-of-comment delimiter, then the comment block will be terminated early. This could result in the browser rendering what was intended to be a comment as part of the page content displayed to the user. To see this, we can try inserting a model filter call that includes the HTML end-of-comment delimiter into the home page view code, and see what the browser shows.

But what is the HTML end-of-comment delimiter? You might guess that it is -->, but in fact it is just the two dashes in a row. Technically, the <! and > are defined as the beginning and end of markup declaration, while the dashes mark the beginning and end of the comment. Thus, a query that contains two dashes in a row should trigger the behavior we are worried about here. To test this, add this line of code to the home view:

Survey.objects.filter(title__contains='--').count()

Note nothing has to be done with the results of the call; the added code must simply ensure that the query containing the two dashes is actually sent to the database. This added line does that by retrieving the count of results matching the pattern containing two dashes. With that added line in the home view, Firefox will display the survey home page like so:

The two dashes in a row in a SQL query value caused Firefox to prematurely terminate the comment block, and data we had intended to be still inside the comment has appeared in the browser page. In order to avoid this, we need to ensure that two dashes in a row never appear in the SQL query values included in the comment block.

A quick glance through the built-in Django filters doesn't reveal any that could be used to replace a string of two dashes with something else. The cut filter could be used to remove them, but simply removing them would make the sql value misleading as there would be no indication that the characters had been removed from the string. Therefore, it seems we will need to develop a custom filter for this.

We will put the custom filter in the gen_utils application. Filters and template tags must be placed in a templatetags module in an application, so we must first create the templatetags directory. Then, we can put an implementation for a replace_dashes filter into a file named gentags.py within gen_utils/templatetags:

from django import template
register = template.Library()
@register.filter
def replace_dashes(value):
return value.replace('--','~~double-dash~~')
replace_dashes.is_safe = True

The bulk of this code is the standard boilerplate import, register assignment, and @register.filter decoration needed to register the replace_dashes function so that it is available for use as a filter. The function itself simply replaces any occurrences of a pair of dashes in a string with ~~double-dash~~ instead. Since there is no way to escape the dashes so that they will not be interpreted as the end of the comment yet still appear as dashes, we replace them with a string describing what had been there. The last line marks the replace_dashes filter as safe, meaning it does not introduce any HTML markup characters that would need to be escaped in its output.

We also need to change the template snippet in gen_utils/showqueries.html to load and use this filter for display of the SQL query values:

{% if sql_queries %}<!--
{% with sql_queries|length as qcount %}
{{ qcount }} quer{{ qcount|pluralize:"y,ies" }}
{% endwith %}
{% load gentags %}
{% for qdict in sql_queries %}
{{ qdict.sql|safe|replace_dashes|wordwrap:60 }} ({{ qdict.time }}
seconds)
{% endfor %}
-->{% endif %}

The only changes here are the addition of the {% load gentags %} line and the addition of replace_dashes in the sequence of filters applied to qdict.sql.

Finally, we can remove the comment snippet from the survey/home.html template. Instead, we will put the new general snippet in the survey/base.html template, so this becomes:

<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Strict//EN"
"http://www.w3.org/TR/xhtml1/DTD/xhtml1-strict.dtd">
<html xmlns="http://www.w3.org/1999/xhtml">
<head>
<title>{% block title %}Survey Central{% endblock %}</title>
</head>
<body>
{% block content %}{% endblock %}
</body>
{% include "gen_utils/showqueries.html" %}
</html>

Placing {% include %} in the base template will cause every template that inherits from base to automatically have the comment block added, assuming that the other conditions of DEBUG being turned on, the requesting IP address being listed in INTERNAL_IPS, and the response being rendered with a RequestContext, are met. We'd likely want to remove this before putting the application in a production environment, but during development it can come in handy to have easy automatic access to the SQL queries used to generate any page.

Summary

In this article, we developed some template utility code to track what SQL requests are made during production of a page.

If you have read this article you may be interested to view :

Django 1.1 Testing and Debugging Building rigorously tested and bug-free Django applications
Published: April 2010
eBook Price: $29.99
Book Price: $49.99
See more
Select your format and quantity:

About the Author :


Karen M. Tracey

    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.            

Books From Packt

CMS Made Simple 1.6: Beginner's Guide
CMS Made Simple 1.6: Beginner's Guide

Moodle 1.9 Teaching Techniques
Moodle 1.9 Teaching Techniques

WordPress 2.8 Themes Cookbook
WordPress 2.8 Themes Cookbook

iReport 3.7
iReport 3.7

TYPO3 4.2 E-Commerce
TYPO3 4.2 E-Commerce

Firebug 1.5: Editing, Debugging, and Monitoring Web Pages
Firebug 1.5: Editing, Debugging, and Monitoring Web Pages

Apache MyFaces 1.2 Web Application Development
Apache MyFaces 1.2 Web Application Development

Oracle Application Express 3.2 – The Essentials and More
Oracle Application Express 3.2 – The Essentials and More

Code Download and Errata
Packt Anytime, Anywhere
Register Books
Print Upgrades
eBook Downloads
Video Support
Contact Us
Awards Voting Nominations Previous Winners
Judges Open Source CMS Hall Of Fame CMS Most Promising Open Source Project Open Source E-Commerce Applications Open Source JavaScript Library Open Source Graphics Software
Resources
Open Source CMS Hall Of Fame CMS Most Promising Open Source Project Open Source E-Commerce Applications Open Source JavaScript Library Open Source Graphics Software