Django: show/log ORM sql calls from python shell

Using the excellent Django-Devserver I'm finding all kinds of interesting and unexpected SQL calls in my code. I wanted to find where the calls are coming from, and so I'm looking for a way to get a log or print-out of all SQL calls generated by the Django ORM in the Python shell. That is, when I do a Django ORM call via the Python shell, I'd like to see the resulting SQL printed out or logged.

I noticed several solutions that add log info to the html page. Is there an easy way to dump to the command line instead?

If you're using Django 1.3:

import logging
l = logging.getLogger('django.db.backends')
l.setLevel(logging.DEBUG)
l.addHandler(logging.StreamHandler())

I was trying to use "https://stackoverflow.com/questions/2314920/django-show-log-orm-sql-calls-from-python-shell/5835465#5835465" in a shell on a production server, and it wasn't working. Eventually someone pointed out that it will only do this debug logging when DEBUG = True. But you can work around that like this:

import logging
from django.db import connection
connection.force_debug_cursor = True  # Change to use_debug_cursor in django < 1.8
l = logging.getLogger('django.db.backends')
l.setLevel(logging.DEBUG)
l.addHandler(logging.StreamHandler())

I'm leaving this here so I can find it later, and hopefully it saves someone else the same digging I did.

Rob Hudson's Django Debug Toolbar, as well as its general awesomness, also includes a pretty nifty debugsqlshell manage.py command which does exactly this.

Use django extensions.

pip install django-extensions
./manage.py shell_plus --print-sql

For production environments it might not work due to debug settings.

If you're in the shell, or anywhere for that matter, you can use the queryset method

query.as_sql()

to print the SQL command.

ie:

MyModel.objects.all().query.as_sql()

qs = YourModel.objects.all()

qs.query.get_compiler('default').as_sql()

If you're really serious about wanting to see/log all SQL queries, you'll want to try Django 1.3 (currently in alpha, but soon to be production) which enables Python loggers for many components, including the database backends.

Of course, if you're stuck using a stable version of Django, you can get the same effect relatively easily by patching django/db/models/sql/compiler.py by adding this to the bottom of the import list:

import logging
_querylogger = logging.getLogger( 'sql.compiler' )

The find the SQLCompiler::execute_sql() method and change:

    cursor = self.connection.cursor()
    cursor.execute( sql, params )

to this:

    cursor = self.connection.cursor()
    _querylogger.info( "%s <= %s", sql, params )
    cursor.execute( sql, params )

Just to mention another option - I've made the django-sql-sniffer tool so that it can attach to any running Python process and monitor/analyze SQL execution coming from Django ORM.

As such it can also be used to monitor queries coming from a Python shell process (see github page for the demo video):

• open shell and get process ID:

In [1]: import os

In [2]: os.getpid()
Out[2]: 99688

• attach django-sql-sniffer in another tab (and in this case specify the tail mode to follow the queries live)

$ django-sql-sniffer -p 99688 -t

• go back to your shell and start executing queries

In [3]: cat library/models.py
from django.db import models


class Book(models.Model):
    title = models.CharField(null=False, blank=False, max_length=100)
    author = models.ForeignKey('Author', on_delete=models.CASCADE)


class Author(models.Model):
    first_name = models.CharField(max_length=30)
    last_name = models.CharField(max_length=30)


In [4]: from library.models import *

In [5]: books = Book.objects.all()

In [6]: len(books)  # better use count
Out[6]: 121000

In [7]: book = books.first()  # query set not ordered, will hit db again

In [8]: book = books.first()  # query set not ordered, will hit db again

In [9]: book = books.first()  # query set not ordered, will hit db again

In [10]: book.author.id  # better use author_id
Out[10]: 1

In [11]: Book.objects.filter(author__first_name__startswith='A').count() > 0
Out[11]: True

In [12]: Book.objects.filter(author__first_name__startswith='A').exists()
Out[12]: True

• the tool prints the raw queries as they get executed

Count: 1; Duration: 0.002211809; Max Duration: 0.002211809; Query:
SELECT "library_book"."id",
       "library_book"."title",
       "library_book"."author_id"
  FROM "library_book"
-------------------------------------------------------
Count: 1; Duration: 0.000240326; Max Duration: 0.000240326; Query:
SELECT "library_book"."id",
       "library_book"."title",
       "library_book"."author_id"
  FROM "library_book"
 ORDER BY "library_book"."id" ASC
 LIMIT 1
-------------------------------------------------------
Count: 2; Duration: 0.000150919; Max Duration: 0.000240326; Query:
SELECT "library_book"."id",
       "library_book"."title",
       "library_book"."author_id"
  FROM "library_book"
 ORDER BY "library_book"."id" ASC
 LIMIT 1
-------------------------------------------------------
Count: 3; Duration: 0.000187874; Max Duration: 0.000240326; Query:
SELECT "library_book"."id",
       "library_book"."title",
       "library_book"."author_id"
  FROM "library_book"
 ORDER BY "library_book"."id" ASC
 LIMIT 1
-------------------------------------------------------
Count: 1; Duration: 0.000919104; Max Duration: 0.000919104; Query:
SELECT "library_author"."id",
       "library_author"."first_name",
       "library_author"."last_name"
  FROM "library_author"
 WHERE "library_author"."id" = %s
 LIMIT 21
-------------------------------------------------------
Count: 1; Duration: 0.040677071; Max Duration: 0.040677071; Query:
SELECT COUNT(*) AS "__count"
  FROM "library_book"
 INNER JOIN "library_author"
    ON ("library_book"."author_id" = "library_author"."id")
 WHERE "library_author"."first_name" LIKE %s ESCAPE '\'
-------------------------------------------------------
Count: 1; Duration: 0.002345800; Max Duration: 0.002345800; Query:
SELECT (1) AS "a"
  FROM "library_book"
 INNER JOIN "library_author"
    ON ("library_book"."author_id" = "library_author"."id")
 WHERE "library_author"."first_name" LIKE %s ESCAPE '\'
 LIMIT 1
-------------------------------------------------------

• finally, hit Ctrl + C to stop the tool and get an analysis of all captured queries

=======================================================

  ____    ___   _       ____  _____   _   _____  ____
 / ___|  / _ \ | |     / ___||_   _| / \ |_   _|/ ___|
 \___ \ | | | || |     \___ \  | |  / _ \  | |  \___ \
  ___) || |_| || |___   ___) | | | / ___ \ | |   ___) |
 |____/  \__\_\|_____| |____/  |_|/_/   \_\|_|  |____/

               Django SQL Sniffer v1.0.0
=======================================================
             TOP QUERIES BY MAX DURATION


Count: 1; Max Duration: 0.040677071; Combined Duration: 0.040677071; Query:
SELECT COUNT(*) AS "__count"
  FROM "library_book"
 INNER JOIN "library_author"
    ON ("library_book"."author_id" = "library_author"."id")
 WHERE "library_author"."first_name" LIKE %s ESCAPE '\'
-------------------------------------------------------
Count: 1; Max Duration: 0.002345800; Combined Duration: 0.002345800; Query:
SELECT (1) AS "a"
  FROM "library_book"
 INNER JOIN "library_author"
    ON ("library_book"."author_id" = "library_author"."id")
 WHERE "library_author"."first_name" LIKE %s ESCAPE '\'
 LIMIT 1
-------------------------------------------------------
Count: 1; Max Duration: 0.002211809; Combined Duration: 0.002211809; Query:
SELECT "library_book"."id",
       "library_book"."title",
       "library_book"."author_id"
  FROM "library_book"
-------------------------------------------------------
=======================================================