Profiling SQL in Pylons with Dozer

So you want to find out why your Pylons app is running slowly? Well most likely it has to do with your SQL queries, and the best way to see what's going on and how long each request is taking is to install Dozer (by benbangert of Pylons), and load it up with a TimerProxy (by zzzeek of SQLAlchemy).

Sound like fun? Well, here's how to do it.

Install Dozer:

sudo easy_install -U http://www.bitbucket.org/bbangert/dozer/get/b748d3e1cc87.gz

Add this to your middleware:

# Add this to your middleware.py, right before return app
    if asbool(config['debug']):
        from dozer import Logview
        app = Logview(app, config)

Add this to your development.ini

# Add to development.ini
logview.sqlalchemy = #faa
logview.pylons.templating = #bfb

(you can customize the colors here)

Next, modify your configuration ini as well as you like to configure what shows up in the log. Note that I have root set to INFO which will squelch a lot of messages. Change this to DEBUG to see more of what's going on in each request.

# Logging configuration
[loggers]
keys = root, YOURPROJ

[handlers]
keys = console

[formatters]
keys = generic

[logger_root]
level = INFO
handlers = console

[logger_YOURPROJ]
level = DEBUG
handlers =
qualname = YOURPROJ.lib

[logger_sqlalchemy]
level = INFO
handlers =
qualname = sqlalchemy.engine

[handler_console]
class = StreamHandler
args = (sys.stderr,)
level = NOTSET
formatter = generic

[formatter_generic]
format = %(asctime)s,%(msecs)03d %(levelname)-5.5s [%(name)s] %(message)s
datefmt = %H:%M:%S

Add this file to /lib/

querytimer.py

from sqlalchemy.interfaces import ConnectionProxy
import time
 
import logging
log = logging.getLogger(__name__)
 
class TimerProxy(ConnectionProxy):
    def cursor_execute(self, execute, cursor, statement, parameters, context, executemany):
        now = time.time()
        try:
            return execute(cursor, statement, parameters, context)
        finally:
            total = time.time() - now
            log.debug("Query: %s" % statement)
            log.debug("Total Time: %f" % total)
 

Okay, one last thing, modify your SQLAlchemy engine in environment.py to this:

engine = engine_from_config(config, 'sqlalchemy.', proxy=TimerProxy())

and add an import at the top:

from YOURPROJ.lib.querytimer import TimerProxy

So that's it! Restart paster, and load up a request in your web browser. There will now be a bar at the top that you can click on and see all the requests.

If you want to run TimerProxy on it's own (that is without Pylons and Dozer, see zzzeek's post on "Timing All Queries".