SQL Profiling (SQLAlchemy) in Pylons with Dozer

Want to understand why your application written using the Pylons framework is so slow? Most likely, it has to be so because of your SQL queries, and the best way to understand what is happening is the amount of time 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 it’s not worth explaining 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 a few 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. By setting the DEBUG level you can see everything that happens with 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 

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 do not forget to add the import TimerProxy to the beginning of the file:

 from YOURPROJ.lib.querytimer import TimerProxy 

That's all! Restart paster and open your project in a browser. From above there will be a narrow strip, by clicking the mouse on which you will receive a list of all the requests that were made to generate the page.

More information about TimerProxy can be found in the blog zzzeek'a