如何配置SQLAlchemy支持的应用程序？

Question

有没有人有经验分析Python/SQLAlchemy应用程序？找到瓶颈和设计缺陷的最佳方法是什么？

我们有一个Python应用程序,其中数据库层由SQLAlchemy处理.该应用程序使用批处理设计,因此许多数据库请求按顺序在有限的时间内完成.目前运行时间太长,因此需要进行一些优化.我们不使用ORM功能,数据库是PostgreSQL.

Answer 1

有时只是简单的SQL日志记录(通过python的日志记录模块启用或通过echo=True参数on 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部分需要334ms.

记录SQL还将说明是否发布了数十个/数百个查询,这些查询可以通过连接更好地组织成更少的查询.使用SQLAlchemy ORM时,"eager loading"功能提供给部分(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's 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将对绑定参数和结果列执行字符串编码/解码,这在所有情况下可能都不需要.

配置文件的输出可能有点令人生畏,但经过一些练习后,它们很容易阅读.曾经有人在邮件列表上声称速度缓慢,在让他发布了配置文件的结果之后,我能够证明速度问题是由于网络延迟 - 在cursor.execute()以及所有Python中花费的时间方法非常快,而大部分时间花在了socket.receive()上.

如果你有野心,那么在SQLAlchemy单元测试中,如果你在http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/test/aaa_profiling周围进行SQLAlchemy分析,那么这个例子也会更加复杂.在那里,我们使用装饰器进行测试,该装饰器断言用于特定操作的最大数量的方法调用,因此如果检查了一些低效的函数,测试将揭示它(重要的是要注意在Python中,函数调用具有最高的任何操作的开销,以及调用次数通常与花费的时间几乎成比例).值得注意的是"zoomark"测试使用了一种奇特的"SQL捕获"方案,该方案从等式中减少了DBAPI的开销 - 尽管这种技术对于花园种类分析并不是必需的.

Answer 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性能的好文章找到)