Blog

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:

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).

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:

fromdjango.dbimportconnectionfromdjango.utils.logimportgetLoggerlogger=getLogger(__name__)classQueryCountDebugMiddleware(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. """defprocess_response(self,request,response):ifresponse.status_code==200:total_time=0forqueryinconnection.queries:query_time=query.get('time')ifquery_timeisNone:# 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)/1000total_time+=float(query_time)logger.debug('%s queries run, total %s seconds'%(len(connection.queries),total_time))returnresponse

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.