Как я могу профилировать приложение с поддержкой SQLAlchemy?

Ответ 1

Иногда просто обычное ведение журнала SQL (включено через модуль протоколирования python или с помощью аргумента echo=True на create_engine()) может дать вам представление о том, как долго это происходит. Например, если вы зарегистрируете что-то сразу после операции SQL, вы увидите что-то подобное в своем журнале:

17:37:48,325 INFO  [sqlalchemy.engine.base.Engine.0x...048c] SELECT ...
17:37:48,326 INFO  [sqlalchemy.engine.base.Engine.0x...048c] {<params>}
17:37:48,660 DEBUG [myapp.somemessage] 

если вы зарегистрировали myapp.somemessage сразу после операции, вы знаете, что для завершения SQL-части вещей потребовалось 334 мс.

Журнал регистрации SQL также будет иллюстрировать, будут ли выпущены десятки/сотни запросов, которые могут быть лучше организованы в гораздо меньшее число запросов через объединения. При использовании ORM SQLAlchemy функция "надежной загрузки" предоставляется частично (contains_eager()) или полностью (eagerload(), eagerload_all()) автоматизирует это действие, но без ORM это просто означает использование объединений, чтобы результаты несколько таблиц могут быть загружены в один результирующий набор вместо умножения числа запросов при добавлении большего количества глубины (т.е. r + r*r2 + r*r2*r3...)

Если ведение журнала показывает, что отдельные запросы занимают слишком много времени, вам потребуется разбивка того, сколько времени было потрачено в базе данных, обрабатывающей запрос, отправляя результаты по сети, обрабатывая DBAPI и, наконец, получая SQLAlchemy и/или ORM-уровень. Каждый из этих этапов может представить свои собственные узкие места в зависимости от специфики.

Для этого вам нужно использовать профилирование, например cProfile или hotshot. Вот декоратор, который я использую:

import cProfile as profiler
import gc, pstats, time

def profile(fn):
    def wrapper(*args, **kw):
        elapsed, stat_loader, result = _profile("foo.txt", fn, *args, **kw)
        stats = stat_loader()
        stats.sort_stats('cumulative')
        stats.print_stats()
        # uncomment this to see who calling what
        # stats.print_callers()
        return result
    return wrapper

def _profile(filename, fn, *args, **kw):
    load_stats = lambda: pstats.Stats(filename)
    gc.collect()

    began = time.time()
    profiler.runctx('result = fn(*args, **kw)', globals(), locals(),
                    filename=filename)
    ended = time.time()

    return ended - began, load_stats, locals()['result']

Чтобы профилировать раздел кода, поместите его в функцию с декоратором:

@profile
def go():
    return Session.query(FooClass).filter(FooClass.somevalue==8).all()
myfoos = go()

Вывод профилирования может быть использован для того, чтобы дать представление о времени, в которое расходуется время. Если, например, вы видите, что все время тратится на cursor.execute(), то вызов DBAPI низкого уровня в базу данных, и это означает, что ваш запрос должен быть оптимизирован либо путем добавления индексов, либо для реструктуризации запроса и/или базовой схемы. Для этой задачи я бы рекомендовал использовать pgadmin вместе со своей графической утилитой EXPLAIN, чтобы увидеть, какую работу выполняет запрос.

Если вы видите много тысяч вызовов, связанных с извлечением строк, это может означать, что ваш запрос возвращает больше строк, чем ожидалось - декартовой продукт из-за неполного соединения может вызвать эту проблему. Еще одна проблема - время, затрачиваемое на обработку типов. Тип SQLAlchemy, такой как Unicode, будет выполнять строковое кодирование/декодирование по параметрам связывания и столбцам результатов, что может не понадобиться во всех случаях.

Вывод профиля может быть немного сложным, но после некоторой практики их очень легко читать. Когда-то кто-то в списке рассылки утверждал, что он медленный, и после того, как он опубликовал результаты профиля, я смог продемонстрировать, что проблемы с скоростью были связаны с задержкой в ​​сети - временем, проведенным в курсоре .execute(), а также всем Python методы были очень быстрыми, тогда как большая часть времени была потрачена на socket.receive().

Если вы чувствуете амбициозность, есть еще более привлекательный пример профилирования SQLAlchemy в модульных тестах SQLAlchemy, если вы ткнете http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/test/aaa_profiling. Там у нас есть тесты с использованием декораторов, которые утверждают, что максимальное количество вызовов методов используется для определенных операций, поэтому, если что-то неэффективное будет проверено, тесты покажут его (важно отметить, что в Python вызовы функций имеют самый высокий накладные расходы на любую операцию, а количество вызовов чаще всего не пропорционально времени). Следует отметить те тесты "zoomark", которые используют причудливую схему "захвата SQL", которая устраняет накладные расходы DBAPI из уравнения - хотя эта техника не нужна для профилирования садовых сортов.

Ответ 2

Там очень полезный рецепт профилирования в SQLAlchemy wiki

С несколькими незначительными изменениями

from sqlalchemy import event
from sqlalchemy.engine import Engine
import time
import logging

logging.basicConfig()
logger = logging.getLogger("myapp.sqltime")
logger.setLevel(logging.DEBUG)

@event.listens_for(Engine, "before_cursor_execute")
def before_cursor_execute(conn, cursor, statement, 
                        parameters, context, executemany):
    context._query_start_time = time.time()
    logger.debug("Start Query:\n%s" % statement)
    # Modification for StackOverflow answer:
    # Show parameters, which might be too verbose, depending on usage..
    logger.debug("Parameters:\n%r" % (parameters,))


@event.listens_for(Engine, "after_cursor_execute")
def after_cursor_execute(conn, cursor, statement, 
                        parameters, context, executemany):
    total = time.time() - context._query_start_time
    logger.debug("Query Complete!")

    # Modification for StackOverflow: times in milliseconds
    logger.debug("Total Time: %.02fms" % (total*1000))

if __name__ == '__main__':
    from sqlalchemy import *

    engine = create_engine('sqlite://')

    m1 = MetaData(engine)
    t1 = Table("sometable", m1, 
            Column("id", Integer, primary_key=True),
            Column("data", String(255), nullable=False),
        )

    conn = engine.connect()
    m1.create_all(conn)

    conn.execute(
        t1.insert(), 
        [{"data":"entry %d" % x} for x in xrange(100000)]
    )

    conn.execute(
        t1.select().where(t1.c.data.between("entry 25", "entry 7800")).order_by(desc(t1.c.data))
    )

Вывод выглядит примерно так:

DEBUG:myapp.sqltime:Start Query:
SELECT sometable.id, sometable.data 
FROM sometable 
WHERE sometable.data BETWEEN ? AND ? ORDER BY sometable.data DESC
DEBUG:myapp.sqltime:Parameters:
('entry 25', 'entry 7800')
DEBUG:myapp.sqltime:Query Complete!
DEBUG:myapp.sqltime:Total Time: 410.46ms

Затем, если вы найдете странно медленный запрос, вы можете взять строку запроса, форматировать в параметрах (может быть выполнено оператор форматирования строки %, по крайней мере, для psycopg2), префикс его с помощью "EXPLAIN ANALYZE" и вытащите вывод плана запроса в http://explain.depesz.com/ (найденный через эта хорошая статья о Производительность PostgreSQL)

Ответ 3

У меня был некоторый успех в использовании cprofile и просмотре результатов в runnakerun. Это, по крайней мере, сказало мне, какие функции и вызовы занимают много времени, и если в базе данных была проблема. Документация здесь. Вам нужно wxpython. презентация на этом хорошо, чтобы вы начали.
Его так же просто, как

import cProfile
command = """foo.run()"""
cProfile.runctx( command, globals(), locals(), filename="output.profile" )

Тогда

python runnake.py output.profile

Если вы хотите оптимизировать свои запросы, вам понадобится postgrsql profiling.

Также стоит записывать записи для записи запросов, но для этого не существует синтаксического анализатора, который я знаю для получения длинных запросов (и он не будет полезен для одновременных запросов).

sqlhandler = logging.FileHandler("sql.log")
sqllogger = logging.getLogger('sqlalchemy.engine')
sqllogger.setLevel(logging.info)
sqllogger.addHandler(sqlhandler)

и убедитесь, что ваш оператор engine имеет echo = True.

Когда я это делал, это был мой код, который был основной проблемой, поэтому cprofile помог.