Профилирование SQL (SQLAlchemy) в Pylons с помощью Dozer

Хотите понять, почему ваше приложение, написанное с помощью фреймворка Pylons, столь медлительное? Скорей всего ему приходится быть таким из-за ваших SQL запросов, и наилучший способ способ понять, что происходит исколько времени тратится на каждый из них — установить Dozer (созданый Беном Бангертом (Ben Bangert) из команды разработчиков Pylons) и добавить в ваше приложение небольшой класс TimerProxy (написанный zzzeek'ом из команды разработчиков SQLALchemy.



Для начала установим Dozer (думаю — не стоит объяснять, что такое easy_install, верно?):

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

Добавляем его в наш config/middleware:

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

Добавляем несколько строк в development.ini:

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

Далее, отредактируйте раздел [loggers] в этом же ini файле. Заметьте, что в моем примере root установлен на уровень INFO, который позволяет увидеть достаточно много сообщений. Установив уровень DEBUG можно увидеть вообще всё, что происходит при каждом запросе

# 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

Создайте в каталоге 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)

Ну и последняя вещь. Поправьте инициализацию sqlalchemy в файле config/environment.py:

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

и не забудьте добавить импорт TimerProxy в начало файла:

from YOURPROJ.lib.querytimer import TimerProxy

Вот и всё! Перезапустите paster и откройте ваш проект в браузере. Сверху будет узкая полоса, нажав мышкой на которую вы получите список всех запросов, которые были выполнены для генерирования страницы.

Подробней про TimerProxy можно узнать в блоге zzzeek'а