Django Decorator to Print SQL Queries

Michael Shepanski
November 27, 2011

Django's ORM is great for fast development, but it is sometimes all too easy to write inefficient queries in the language. There are a few options to help find rogue queries sucking all that process time. My favorite is of course Django Debug Toolbar. However, sometimes this is not a viable option, such as when writing AJAX processors, or for some reason DDTB is not available to you.

This simple decorator may help you alleviate some pain. It also becomes a useful tool to copy and paste the queries into an external query browser. My favorite for Linux is CrunchyFrog.

import os

COLORS = {'blue':34, 'cyan':36, 'green':32, 'grey':30, 'magenta':35, 'red':31, 'white':37, 'yellow':33}
RESET = '\033[0m'

def print_queries(filter=None):
    """ Print all queries executed in this funnction. """
    def wrapper1(func):
        def wrapper2(*args, **kwargs):
            from django.db import connection
            sqltime, longest, numshown = 0.0, 0.0, 0
            initqueries = len(connection.queries)
            starttime = time.time()
            result = func(*args, **kwargs)
            for query in connection.queries[initqueries:]:
                sqltime += float(query['time'].strip('[]s'))
                longest = max(longest, float(query['time'].strip('[]s')))
                if not filter or filter in query['sql']:
                    numshown += 1
                    querystr = colored('\n[%ss] ' % query['time'], 'yellow')
                    querystr += colored(query['sql'], 'blue')
                    print querystr
            numqueries = len(connection.queries) - initqueries
            numhidden = numqueries - numshown
            runtime = round(time.time() - starttime, 3)
            proctime = round(runtime - sqltime, 3)
            print colored("------", 'blue')
            print colored('Total Time:  %ss' % runtime, 'yellow')
            print colored('Proc Time:   %ss' % proctime, 'yellow')
            print colored('Query Time:  %ss (longest: %ss)' % (sqltime, longest), 'yellow')
            print colored('Num Queries: %s (%s hidden)\n' % (numqueries, numhidden), 'yellow')
            return result
        return wrapper2
    return wrapper1

def colored(text, color=None):
    """ Colorize text {red, green, yellow, blue, magenta, cyan, white}. """
    if os.getenv('ANSI_COLORS_DISABLED') is None:
        fmt_str = '\033[%dm%s'
        if color is not None:
            text = fmt_str % (COLORS[color], text)
        text += RESET
    return text

And here is an obligatory usage example. You can optionally send an a single filter argument that would not display the query unless the specified string exists in the query. In the example below, I am only display queries with the word 'metric' in them.

def function_with_queries():
    # Do something here that runs some Django queries
    # Perhaps just wrap your page view

>> [0.023s] SELECT (CAST(label AS int)) AS "range", SUM("api_metrics_heuristic"."value") AS "sum" FROM "api_metrics_heuristic" WHERE ("api_metrics_heuristic"."type" = E'sizes'  AND "api_metrics_heuristic"."headfiler_id" IN (SELECT U0."id" FROM "accounts_filer" U0 INNER JOIN "auth_user" U1 ON (U0."user_id" = U1."id") LEFT OUTER JOIN "accounts_account" U2 ON (U1."id" = U2."user_id") WHERE (NOT (U1."is_staff" = true ) AND U2."account_deleted" IS NULL))) GROUP BY (CAST(label AS int)), CAST(label AS int) ORDER BY "range" ASC
>> ------
>> Total Time:  0.399s
>> Proc Time:   0.301s
>> Query Time:  0.098s (longest: 0.037s)
>> Num Queries: 27 (26 hidden)

comments powered by Disqus