SQL Profiling (SQLAlchemy) in Pylons with Dozer

Want to see why your Pylons framework application is so slow? Most likely he has to be like that because of your SQL queries, and the best way to understand what happens is how much time is spent on each of them - install Dozer (created by Ben Bangert from the Pylons development team) and add a small class TimerProxy (written by zzzeek from the SQLALchemy development team.



First, install Dozer (I think - you should not explain what easy_install is, right?):

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

Add it to our config / middleware:

# Добавьте это в middleware.py, непосредственно перед возвращением app
    if asbool(config['debug']):
        from dozer import Logview
        app = Logview(app, config)

Add some lines to development.ini:

logview.sqlalchemy = #faa
logview.pylons.templating = #bfb

Next, edit the [loggers] section in the same ini file. Note that in my example, root is set to the INFO level, which allows you to see quite a lot of messages. Having set the DEBUG level, you can see everything that happens with every 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

Create a querytimer.py file in the lib / directory with the following contents:

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)

Well, the last thing. Correct the sqlalchemy initialization in the config / environment.py: file

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

and remember to add the TimerProxy import to the top of the file:

from YOURPROJ.lib.querytimer import TimerProxy

That's all! Restart paster and open your project in a browser. There will be a narrow bar at the top, clicking on which you will get a list of all the requests that were performed to generate the page.

Learn more about TimerProxy on zzzeek's blog.