我如何分析一个SQLAlchemy驱动的应用程序？
有没有人有经验分析一个Python / SQLAlchemy应用程序？ 寻找瓶颈和devise缺陷的最好方法是什么？
我们有一个Python应用程序，数据库层由SQLAlchemy处理。 应用程序使用批处理devise，所以很多数据库请求都是在有限的时间内按顺序完成的。 目前运行需要太长时间，因此需要进行一些优化。 我们不使用ORMfunction，而数据库是PostgreSQL。
有时候，简单的SQL日志logging（通过python的日志logging模块启用，或者通过create_engine()的echo=True参数）可以让你知道事情要花多长时间。 例如，如果你在SQL操作之后logging一些东西，你会在日志中看到类似这样的东西：
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]
如果您在操作之后立即logging了myapp.somemessage ，则知道完成SQL部分的操作需要334ms。
loggingSQL还将说明是否有几十个/数百个查询正在发布，这可以通过连接更好地组织成更less的查询。 当使用SQLAlchemy ORM时，部分（ contains_eager() ）或完全（ eagerload() ， eagerload_all() ）提供了“ eagerload()加载”function，使这个活动自动化，但是没有ORM，它只是意味着使用连接，可以将多个表加载到一个结果集中，而不是在添加更多深度时将查询数相乘（即r + r*r2 + r*r2*r3 …）
如果日志logging显示个别查询花费的时间过长，则需要细分处理查询的数据库花了多less时间，通过networking发送结果，由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调用，这意味着您的查询应该优化，可以通过添加索引或重新构build查询和/或基础架构。 对于这个任务，我build议使用pgadmin以及其graphics化的EXPLAIN实用程序来查看查询正在做什么样的工作。
如果您看到与访存行有关的数千次调用，则可能意味着您的查询正在返回比预期更多的行 – 由于未完成连接而导致的笛卡尔产品可能会导致此问题。 还有一个问题是在types处理中花费的时间 – 诸如Unicode之类的SQLAlchemytypes将对绑定参数和结果列执行string编码/解码，这在所有情况下可能都不需要。
一个configuration文件的输出可能有点令人生畏，但经过一些练习，他们很容易阅读。 在邮件列表上曾有人声称速度缓慢，在让他发布configuration文件的结果之后，我能够certificate速度问题是由networking延迟引起的 – 在cursor.execute（）以及所有Python方法非常快，而大部分时间都花在socket.receive（）上。
如果你觉得雄心勃勃，那么在SQLAlchemyunit testing中，如果你在http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/test/aaa_profiling中find SQLAlchemy分析的话，还有一个更复杂的示例。 在那里，我们使用装饰器进行testing，这些装饰器声明了用于特定操作的最大数量的方法调用，所以如果检查到效率低下的东西，testing将会显示它（注意在Python中，函数调用具有最高的任何操作的开销，以及通话计数通常与花费的时间几乎成正比）。 值得注意的是，使用花哨的“SQL捕获”scheme的“zoomark”testing可以从等式中删除DBAPI的开销 – 尽pipe这种技术对于花园types的分析并不是真的需要。
SQLAlchemy wiki上有非常有用的configuration文件
通过一些小的修改，
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
那么如果你发现一个奇怪的慢查询，你可以把查询string，参数的格式（至lesspsycopg2可以完成% string-formatting操作符），用“EXPLAIN ANALYZE”作为前缀，并将查询计划输出到http://explain.depesz.com/ （通过这篇关于PostgreSQL性能的好文章find）
我在使用cprofile和在runnakerun中查看结果方面取得了一些成功。 这至less告诉我哪些function和调用花了很长时间，如果数据库是问题。 文档在这里 。 你需要wxpython。 这个介绍很好，让你开始。
它像一样容易
import cProfile command = """foo.run()""" cProfile.runctx( command, globals(), locals(), filename="output.profile" )
然后
python runsnake.py output.profile
如果您正在寻找优化您的查询，您将需要postgrsql分析 。
logging查询也是值得的，但是我没有parsing器来获取长时间运行的查询（对于并发请求它不会有用）。
sqlhandler = logging.FileHandler("sql.log") sqllogger = logging.getLogger('sqlalchemy.engine') sqllogger.setLevel(logging.info) sqllogger.addHandler(sqlhandler)
并确保你的创build引擎语句有echo = True。
当我这样做，实际上是我的代码是主要问题，所以cprofile的事情帮助。
