Django 1.3, released back in March, added built-in support for Python’s logging module. This is very useful for logging in your own code, but it also means you can get a better idea of what Django is doing behind the scenes. At the moment, Django is only using its own logging infrastructure in a few places (this is likely to expand in the future), but we can still do some useful stuff.
Django’s ORM makes interacting with your database extremely quick and painless, but it’s sometimes helpful (or even essential) to peek under the hood and see exactly what the SQL being generated looks like. Django logs all of its queries under the name django.db.backends.
SQL logging in the shell
The first tip comes from Jacob Kaplan-Moss. This allows you to see the queries that are being run “live”, while interactively exploring your models in a Python shell:
import logging
>>> l = logging.getLogger('django.db.backends')
>>> l.setLevel(logging.DEBUG)
>>> l.addHandler(logging.StreamHandler())
>>> from blog.models import Entry
>>> Entry.objects.all()
(0.069) SELECT "blog_entry"."id", "blog_entry"."published", "blog_entry"."title", "blog_entry"."slug", "blog_entry"."published_on", "blog_entry"."author_id" FROM "blog_entry" ORDER BY "blog_entry"."published_on" DESC LIMIT 21; args=()
[<Entry: Logging SQL queries with Django 1.3>, <Entry: Another post>, ...]
Logging all SQL queries
To log all SQL queries, you’ll need to add a few things to your LOGGING configuration dictionary in your settings.py. First, you’ll need a handler. The example below logs everything at DEBUG level to the console (it’ll appear in the output from Django’s built-in development server).
LOGGING = {
...
'handlers': {
...
'console': {
'level': 'DEBUG',
'class': 'logging.StreamHandler',
},
...
},
...
}
Next, you’ll need to add a logger that logs to this handler:
LOGGING = {
...
'loggers': {
...
'django.db.backends': {
'level': 'DEBUG',
'handlers': ['console'],
},
...
},
...
}
Once the above is set up, you should see a stream of SQL queries in your runserver output. You might find, though, that this level of output is too verbose. It can be useful for debugging individual SQL queries, but it’s a bit heavyweight for general use.
Once the above is set up, you should see a stream of SQL queries in your runserver output. You might find, though, that this level of output is too verbose. It can be useful for debugging individual SQL queries, but it’s a bit heavyweight for general use.
Logging query counts per request
When you’re analysing the performance of your application, you often care more about how many queries are being run for a particular request, rather than exactly what they are. This is a bit more fiddly, but it is possible. You’ll need to add a custom middleware to your application that looks something like the following:
from django.db import connection
from django.utils.log import getLogger
logger = getLogger(__name__)
class QueryCountDebugMiddleware(object):
"""
This middleware will log the number of queries run
and the total time taken for each request (with a
status code of 200). It does not currently support
multi-db setups.
"""
def process_response(self, request, response):
if response.status_code == 200:
total_time = 0
for query in connection.queries:
query_time = query.get('time')
if query_time is None:
# django-debug-toolbar monkeypatches the connection
# cursor wrapper and adds extra information in each
# item in connection.queries. The query time is stored
# under the key "duration" rather than "time" and is
# in milliseconds, not seconds.
query_time = query.get('duration', 0) / 1000
total_time += float(query_time)
logger.debug('%s queries run, total %s seconds' % (len(connection.queries), total_time))
return response
This middleware should be the first item in your your MIDDLEWARE_CLASSES setting. Note the actual path will depend on where you put the above snippet.
if DEBUG:
MIDDLEWARE_CLASSES = ('path.to.middleware.QueryCountDebugMiddleware',) + MIDDLEWARE_CLASSES
Finally, you need to configure your LOGGING setting to capture this output. Add a console handler as above, then add a logger. Again, the actual path will depend on the location of your middleware.
LOGGING = {
...
'loggers': {
...
'path.to.middleware': {
'handlers': ['console'],
'level': 'DEBUG',
},
...
},
...
}
Each request to your development server should now result in something like this:
DEBUG 2011-06-22 16:59:52,073 11 queries run, total 0.694647 seconds
[22/Jun/2011 16:59:52] "GET / HTTP/1.1" 200 147893
Much more useful!
