Does anyone have experience profiling a Python/SQLAlchemy app? And what are the best way to find bottlenecks and design flaws?
有人有分析Python/SQLAlchemy应用程序的经验吗?找到瓶颈和设计缺陷的最佳方法是什么?
We have a Python application where the database layer is handled by SQLAlchemy. The application uses a batch design, so a lot of database requests is done sequentially and in a limited timespan. It currently takes a bit too long to run, so some optimization is needed. We don't use the ORM functionality, and the database is PostgreSQL.
我们有一个Python应用程序，其中数据库层由SQLAlchemy处理。应用程序使用批处理设计，因此许多数据库请求是按顺序和有限的时间间隔完成的。目前运行时间有点长，因此需要进行一些优化。我们不使用ORM功能，数据库是PostgreSQL。
3 个解决方案
#1
64
Sometimes just plain SQL logging (enabled via python's logging module or via the echo=True argument on create_engine()) can give you an idea how long things are taking. For example if you log something right after a SQL operation, you'd see something like this in your log:
有时候，仅仅是简单的SQL日志记录(通过python的日志模块或create_engine()上的echo=True参数启用)就可以让您知道事情要花多长时间。例如，如果您在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]
if you logged myapp.somemessage right after the operation, you know it took 334ms to complete the SQL part of things.
如果你登录myapp。在操作之后，您知道完成SQL部分需要334ms。
Logging SQL will also illustrate if dozens/hundreds of queries are being issued which could be better organized into much fewer queries via joins. When using the SQLAlchemy ORM, the "eager loading" feature is provided to partially (contains_eager()) or fully (eagerload(), eagerload_all()) automate this activity, but without the ORM it just means to use joins so that results across multiple tables can be loaded in one result set instead of multiplying numbers of queries as more depth is added (i.e. r + r*r2 + r*r2*r3 ...)
记录SQL还将说明是否发出了数十个/数百个查询，可以通过连接更好地组织成更少的查询。当使用SQLAlchemy ORM,“立即加载”功能是提供给部分(contains_eager())或完全(eagerload(),eagerload_all())自动化这个活动,但是没有ORM只是使用跨多个表连接,这样的结果可以加载在一个数字相乘的结果集,而不是查询添加更多的深度(即r + r * r2 + r * r2 * r3…)
If logging reveals that individual queries are taking too long, you'd need a breakdown of how much time was spent within the database processing the query, sending results over the network, being handled by the DBAPI, and finally being received by SQLAlchemy's result set and/or ORM layer. Each of these stages can present their own individual bottlenecks, depending on specifics.
如果日志记录显示单个查询花费的时间太长，那么您需要详细说明在数据库中处理查询、通过网络发送结果、由DBAPI处理、最终由SQLAlchemy的结果集和/或ORM层接收的时间。根据具体情况，每个阶段都可以呈现各自的瓶颈。
For that you need to use profiling, such as cProfile or hotshot. Here is a decorator I use:
因为您需要使用概要文件，例如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']
To profile a section of code, place it in a function with the decorator:
要配置一段代码，请将其放在与decorator关联的函数中:
@profile
def go():
return Session.query(FooClass).filter(FooClass.somevalue==8).all()
myfoos = go()
The output of profiling can be used to give an idea where time is being spent. If for example you see all the time being spent within cursor.execute(), that's the low level DBAPI call to the database, and it means your query should be optimized, either by adding indexes or restructuring the query and/or underlying schema. For that task I would recommend using pgadmin along with its graphical EXPLAIN utility to see what kind of work the query is doing.
分析的输出可以用来提供时间花在哪里的想法。例如，如果您看到在cursor.execute()中花费的所有时间，这是对数据库的低级DBAPI调用，这意味着您的查询应该进行优化，方法是添加索引或重构查询和/或底层模式。对于该任务，我建议使用pgadmin及其图形解释实用程序来查看查询正在执行何种工作。
If you see many thousands of calls related to fetching rows, it may mean your query is returning more rows than expected - a cartesian product as a result of an incomplete join can cause this issue. Yet another issue is time spent within type handling - a SQLAlchemy type such as Unicode will perform string encoding/decoding on bind parameters and result columns, which may not be needed in all cases.
如果您看到数千个与获取行相关的调用，这可能意味着您的查询返回的行比预期的要多——由于连接不完整而导致的笛卡尔积可能导致这个问题。另一个问题是在类型处理中花费的时间——SQLAlchemy类型(如Unicode)将对绑定参数和结果列执行字符串编码/解码，这在所有情况下可能都不需要。
The output of a profile can be a little daunting but after some practice they are very easy to read. There was once someone on the mailing list claiming slowness, and after having him post the results of profile, I was able to demonstrate that the speed problems were due to network latency - the time spent within cursor.execute() as well as all Python methods was very fast, whereas the majority of time was spent on socket.receive().
概要文件的输出可能有点令人生畏，但是经过一些实践之后，它们非常容易阅读。曾经有人在邮件列表上声称缓慢,之后他职位概要文件的结果,我能证明速度问题是由于网络延迟,所花费的时间内cursor.execute()以及所有Python方法非常快,而大部分时间是花在socket.receive()。
If you're feeling ambitious, there's also a more involved example of SQLAlchemy profiling within the SQLAlchemy unit tests, if you poke around http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/test/aaa_profiling . There, we have tests using decorators that assert a maximum number of method calls being used for particular operations, so that if something inefficient gets checked in, the tests will reveal it (it is important to note that in Python, function calls have the highest overhead of any operation, and the count of calls is more often than not nearly proportional to time spent). Of note are the the "zoomark" tests which use a fancy "SQL capturing" scheme which cuts out the overhead of the DBAPI from the equation - although that technique isn't really necessary for garden-variety profiling.
如果您感到雄心勃勃，那么在SQLAlchemy单元测试中还有一个更复杂的SQLAlchemy剖析示例，如果您在http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/test/aaa_profiling中查找的话。那里,我们测试使用decorator断言方法调用的最大数量被用于特定的操作,所以,如果一些效率低下的签入,测试将显示它(重要的是要注意,在Python中,函数调用的开销最高任何操作,和调用的计算往往几乎与时间成正比)。值得注意的是，“zoomark”测试使用了一种奇特的“SQL捕获”方案，它从等式中减少了DBAPI的开销——尽管这种技术对于普通的概要分析来说并不是必需的。
#2
41
There's an extremely useful profiling recipe on the SQLAlchemy wiki
SQLAlchemy wiki上有一个非常有用的分析配方
With a couple of minor modifications,
通过一些小小的修改，
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 * 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 *: 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))
)
Output is something like:
输出是:
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
Then if you find an oddly slow query, you could take the query string, format in the parameters (can be done the % string-formatting operator, for psycopg2 at least), prefix it with "EXPLAIN ANALYZE" and shove the query plan output into http://explain.depesz.com/ (found via this good article on PostgreSQL performance)
然后，如果找到一个异常缓慢的查询，可以使用查询字符串、参数的格式(至少可以使用% string-格式化操作符，至少是psycopg2)，在它前面加上“EXPLAIN ANALYZE”，然后将查询计划输出推入http://explain.depesz.com/(通过这篇关于PostgreSQL性能的好文章找到)
#3
3
I have had some success in using cprofile and looking at the results in runsnakerun. This at least told me what functions and calls where taking a long time and if the database was the issue. The documentation is here. You need wxpython. The presentation on it is good to get you started.
Its as easy as
我在使用cprofile和查看runsnakerun的结果方面取得了一些成功。这至少告诉了我什么函数和调用需要花费很长时间，以及数据库是否存在问题。这里的文档。你需要wxpython。关于它的介绍很好地让你开始。它的那么容易
import cProfile
command = """foo.run()"""
cProfile.runctx( command, globals(), locals(), filename="output.profile" )
Then
然后
python runsnake.py output.profile
python runsnake。py output.profile
If you are looking to optimise your queries you will need postgrsql profiling.
如果要优化查询，需要postgrsql分析。
It is also worth putting logging on to record the queries, but there is no parser for this that I know of to get the long running queries (and it wont be useful for concurrent requests).
记录查询也值得一试，但是我知道没有解析器可以获得长时间运行的查询(对于并发请求来说，它没有用处)。
sqlhandler = logging.FileHandler("sql.log")
sqllogger = logging.getLogger('sqlalchemy.engine')
sqllogger.setLevel(logging.info)
sqllogger.addHandler(sqlhandler)
and making sure your create engine statement has echo = True.
确保你的create engine语句具有echo = True。
When I did it is was actually my code that was the main issue, so the cprofile thing helped.
当我这么做的时候，我的代码是主要的问题，所以cprofile的事情很有帮助。
#1
64
Sometimes just plain SQL logging (enabled via python's logging module or via the echo=True argument on create_engine()) can give you an idea how long things are taking. For example if you log something right after a SQL operation, you'd see something like this in your log:
有时候，仅仅是简单的SQL日志记录(通过python的日志模块或create_engine()上的echo=True参数启用)就可以让您知道事情要花多长时间。例如，如果您在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]
if you logged myapp.somemessage right after the operation, you know it took 334ms to complete the SQL part of things.
如果你登录myapp。在操作之后，您知道完成SQL部分需要334ms。
Logging SQL will also illustrate if dozens/hundreds of queries are being issued which could be better organized into much fewer queries via joins. When using the SQLAlchemy ORM, the "eager loading" feature is provided to partially (contains_eager()) or fully (eagerload(), eagerload_all()) automate this activity, but without the ORM it just means to use joins so that results across multiple tables can be loaded in one result set instead of multiplying numbers of queries as more depth is added (i.e. r + r*r2 + r*r2*r3 ...)
记录SQL还将说明是否发出了数十个/数百个查询，可以通过连接更好地组织成更少的查询。当使用SQLAlchemy ORM,“立即加载”功能是提供给部分(contains_eager())或完全(eagerload(),eagerload_all())自动化这个活动,但是没有ORM只是使用跨多个表连接,这样的结果可以加载在一个数字相乘的结果集,而不是查询添加更多的深度(即r + r * r2 + r * r2 * r3…)
If logging reveals that individual queries are taking too long, you'd need a breakdown of how much time was spent within the database processing the query, sending results over the network, being handled by the DBAPI, and finally being received by SQLAlchemy's result set and/or ORM layer. Each of these stages can present their own individual bottlenecks, depending on specifics.
如果日志记录显示单个查询花费的时间太长，那么您需要详细说明在数据库中处理查询、通过网络发送结果、由DBAPI处理、最终由SQLAlchemy的结果集和/或ORM层接收的时间。根据具体情况，每个阶段都可以呈现各自的瓶颈。
For that you need to use profiling, such as cProfile or hotshot. Here is a decorator I use:
因为您需要使用概要文件，例如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']
To profile a section of code, place it in a function with the decorator:
要配置一段代码，请将其放在与decorator关联的函数中:
@profile
def go():
return Session.query(FooClass).filter(FooClass.somevalue==8).all()
myfoos = go()
The output of profiling can be used to give an idea where time is being spent. If for example you see all the time being spent within cursor.execute(), that's the low level DBAPI call to the database, and it means your query should be optimized, either by adding indexes or restructuring the query and/or underlying schema. For that task I would recommend using pgadmin along with its graphical EXPLAIN utility to see what kind of work the query is doing.
分析的输出可以用来提供时间花在哪里的想法。例如，如果您看到在cursor.execute()中花费的所有时间，这是对数据库的低级DBAPI调用，这意味着您的查询应该进行优化，方法是添加索引或重构查询和/或底层模式。对于该任务，我建议使用pgadmin及其图形解释实用程序来查看查询正在执行何种工作。
If you see many thousands of calls related to fetching rows, it may mean your query is returning more rows than expected - a cartesian product as a result of an incomplete join can cause this issue. Yet another issue is time spent within type handling - a SQLAlchemy type such as Unicode will perform string encoding/decoding on bind parameters and result columns, which may not be needed in all cases.
如果您看到数千个与获取行相关的调用，这可能意味着您的查询返回的行比预期的要多——由于连接不完整而导致的笛卡尔积可能导致这个问题。另一个问题是在类型处理中花费的时间——SQLAlchemy类型(如Unicode)将对绑定参数和结果列执行字符串编码/解码，这在所有情况下可能都不需要。
The output of a profile can be a little daunting but after some practice they are very easy to read. There was once someone on the mailing list claiming slowness, and after having him post the results of profile, I was able to demonstrate that the speed problems were due to network latency - the time spent within cursor.execute() as well as all Python methods was very fast, whereas the majority of time was spent on socket.receive().
概要文件的输出可能有点令人生畏，但是经过一些实践之后，它们非常容易阅读。曾经有人在邮件列表上声称缓慢,之后他职位概要文件的结果,我能证明速度问题是由于网络延迟,所花费的时间内cursor.execute()以及所有Python方法非常快,而大部分时间是花在socket.receive()。
If you're feeling ambitious, there's also a more involved example of SQLAlchemy profiling within the SQLAlchemy unit tests, if you poke around http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/test/aaa_profiling . There, we have tests using decorators that assert a maximum number of method calls being used for particular operations, so that if something inefficient gets checked in, the tests will reveal it (it is important to note that in Python, function calls have the highest overhead of any operation, and the count of calls is more often than not nearly proportional to time spent). Of note are the the "zoomark" tests which use a fancy "SQL capturing" scheme which cuts out the overhead of the DBAPI from the equation - although that technique isn't really necessary for garden-variety profiling.
如果您感到雄心勃勃，那么在SQLAlchemy单元测试中还有一个更复杂的SQLAlchemy剖析示例，如果您在http://www.sqlalchemy.org/trac/browser/sqlalchemy/trunk/test/aaa_profiling中查找的话。那里,我们测试使用decorator断言方法调用的最大数量被用于特定的操作,所以,如果一些效率低下的签入,测试将显示它(重要的是要注意,在Python中,函数调用的开销最高任何操作,和调用的计算往往几乎与时间成正比)。值得注意的是，“zoomark”测试使用了一种奇特的“SQL捕获”方案，它从等式中减少了DBAPI的开销——尽管这种技术对于普通的概要分析来说并不是必需的。
#2
41
There's an extremely useful profiling recipe on the SQLAlchemy wiki
SQLAlchemy wiki上有一个非常有用的分析配方
With a couple of minor modifications,
通过一些小小的修改，
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 * 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 *: 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))
)
Output is something like:
输出是:
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
Then if you find an oddly slow query, you could take the query string, format in the parameters (can be done the % string-formatting operator, for psycopg2 at least), prefix it with "EXPLAIN ANALYZE" and shove the query plan output into http://explain.depesz.com/ (found via this good article on PostgreSQL performance)
然后，如果找到一个异常缓慢的查询，可以使用查询字符串、参数的格式(至少可以使用% string-格式化操作符，至少是psycopg2)，在它前面加上“EXPLAIN ANALYZE”，然后将查询计划输出推入http://explain.depesz.com/(通过这篇关于PostgreSQL性能的好文章找到)
#3
3
I have had some success in using cprofile and looking at the results in runsnakerun. This at least told me what functions and calls where taking a long time and if the database was the issue. The documentation is here. You need wxpython. The presentation on it is good to get you started.
Its as easy as
我在使用cprofile和查看runsnakerun的结果方面取得了一些成功。这至少告诉了我什么函数和调用需要花费很长时间，以及数据库是否存在问题。这里的文档。你需要wxpython。关于它的介绍很好地让你开始。它的那么容易
import cProfile
command = """foo.run()"""
cProfile.runctx( command, globals(), locals(), filename="output.profile" )
Then
然后
python runsnake.py output.profile
python runsnake。py output.profile
If you are looking to optimise your queries you will need postgrsql profiling.
如果要优化查询，需要postgrsql分析。
It is also worth putting logging on to record the queries, but there is no parser for this that I know of to get the long running queries (and it wont be useful for concurrent requests).
记录查询也值得一试，但是我知道没有解析器可以获得长时间运行的查询(对于并发请求来说，它没有用处)。
sqlhandler = logging.FileHandler("sql.log")
sqllogger = logging.getLogger('sqlalchemy.engine')
sqllogger.setLevel(logging.info)
sqllogger.addHandler(sqlhandler)
and making sure your create engine statement has echo = True.
确保你的create engine语句具有echo = True。
When I did it is was actually my code that was the main issue, so the cprofile thing helped.
当我这么做的时候，我的代码是主要的问题，所以cprofile的事情很有帮助。