SqlAlchemy 2.0 中文文档（五十四）（3）-阿里云开发者社区

SqlAlchemy 2.0 中文文档（五十四）（2）https://developer.aliyun.com/article/1563180

如何对由 SQLAlchemy 驱动的应用进行性能分析？

寻找性能问题通常涉及两种策略。一种是查询分析，另一种是代码分析。

查询分析

有时候，仅仅通过普通的 SQL 记录（通过 python 的 logging 模块启用，或者通过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]

如果你在操作之后记录了 myapp.somemessage，你就知道完成 SQL 部分花费了 334ms。

记录 SQL 也会说明是否发出了数十/数百个查询，这些查询可以更好地组织成更少的查询。在使用 SQLAlchemy ORM 时，“急加载”功能提供了部分 (contains_eager()) 或完全 (joinedload(), subqueryload()) 自动化此活动，但是没有 ORM 的“急加载”通常意味着使用连接，以便跨多个表加载结果集，而不是随着深度的增加而增加查询次数（即 r + r*r2 + r*r2*r3 …）

对于更长期的查询分析，或者实现应用程序端的“慢查询”监视器，可以使用事件拦截游标执行，使用以下类似的方法：

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):
    conn.info.setdefault("query_start_time", []).append(time.time())
    logger.debug("Start Query: %s", statement)
@event.listens_for(Engine, "after_cursor_execute")
def after_cursor_execute(conn, cursor, statement, parameters, context, executemany):
    total = time.time() - conn.info["query_start_time"].pop(-1)
    logger.debug("Query Complete!")
    logger.debug("Total Time: %f", total)

在上面的例子中，我们使用 ConnectionEvents.before_cursor_execute() 和 ConnectionEvents.after_cursor_execute() 事件来建立在执行语句时的拦截点。我们使用 info 字典在连接上附加一个计时器；我们在这里使用堆栈，以处理游标执行事件可能嵌套的偶发情况。

代码分析

如果日志显示单个查询花费的时间过长，您需要了解在数据库内部处理查询、通过网络发送结果、由 DBAPI 处理以及最终由 SQLAlchemy 的结果集和/或 ORM 层接收的时间分别花费了多少。每个阶段都可能出现自己的瓶颈，具体取决于具体情况。

为此，您需要使用 Python Profiling Module。以下是一个将分析集成到上下文管理器中的简单示例：

import cProfile
import io
import pstats
import contextlib
@contextlib.contextmanager
def profiled():
    pr = cProfile.Profile()
    pr.enable()
    yield
    pr.disable()
    s = io.StringIO()
    ps = pstats.Stats(pr, stream=s).sort_stats("cumulative")
    ps.print_stats()
    # uncomment this to see who's calling what
    # ps.print_callers()
    print(s.getvalue())

要对代码段进行分析：

with profiled():
    session.scalars(select(FooClass).where(FooClass.somevalue == 8)).all()

分析的输出可以用来了解时间花费在哪里。分析输出的一部分看起来像这样：

13726 function calls (13042 primitive calls) in 0.014 seconds
Ordered by: cumulative time
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
222/21    0.001    0.000    0.011    0.001 lib/sqlalchemy/orm/loading.py:26(instances)
220/20    0.002    0.000    0.010    0.001 lib/sqlalchemy/orm/loading.py:327(_instance)
220/20    0.000    0.000    0.010    0.000 lib/sqlalchemy/orm/loading.py:284(populate_state)
   20    0.000    0.000    0.010    0.000 lib/sqlalchemy/orm/strategies.py:987(load_collection_from_subq)
   20    0.000    0.000    0.009    0.000 lib/sqlalchemy/orm/strategies.py:935(get)
    1    0.000    0.000    0.009    0.009 lib/sqlalchemy/orm/strategies.py:940(_load)
   21    0.000    0.000    0.008    0.000 lib/sqlalchemy/orm/strategies.py:942(<genexpr>)
    2    0.000    0.000    0.004    0.002 lib/sqlalchemy/orm/query.py:2400(__iter__)
    2    0.000    0.000    0.002    0.001 lib/sqlalchemy/orm/query.py:2414(_execute_and_instances)
    2    0.000    0.000    0.002    0.001 lib/sqlalchemy/engine/base.py:659(execute)
    2    0.000    0.000    0.002    0.001 lib/sqlalchemy/sql/elements.py:321(_execute_on_connection)
    2    0.000    0.000    0.002    0.001 lib/sqlalchemy/engine/base.py:788(_execute_clauseelement)
...

在上面的例子中，我们可以看到 instances() SQLAlchemy 函数被调用了 222 次（递归调用，并且从外部调用了 21 次），所有调用总共花费了 .011 秒。

执行速度慢

这些调用的具体信息可以告诉我们时间花费在哪里。例如，如果您看到时间花费在 cursor.execute() 内部，例如针对 DBAPI：

2    0.102    0.102    0.204    0.102 {method 'execute' of 'sqlite3.Cursor' objects}

这表明数据库启动返回结果花费了很长时间，这意味着你的查询应该进行优化，可以通过添加索引或重构查询和/或底层模式来实现。对于这项任务，有必要分析查询计划，使用诸如 EXPLAIN、SHOW PLAN 等数据库后端提供的系统。

结果获取缓慢 - Core

另一方面，如果您看到与获取行相关的成千上万次调用，或者对 fetchall() 的调用非常长，这可能意味着您的查询返回的行数比预期的多，或者获取行本身很慢。ORM 本身通常使用 fetchall() 来获取行（或者如果使用了 Query.yield_per() 选项，则使用 fetchmany()）。

非常大量的行数将通过在 DBAPI 级别非常慢的调用 fetchall() 来表示：

2    0.300    0.600    0.300    0.600 {method 'fetchall' of 'sqlite3.Cursor' objects}

即使最终结果似乎没有很多行，但出现意外地大量行的情况可能是笛卡尔积的结果 - 当多组行未经适当连接地组合在一起时。如果在复杂查询中使用了错误的 Column 对象，导致引入意外的额外 FROM 子句，那么用 SQLAlchemy Core 或 ORM 查询往往很容易产生这种行为。

另一方面，在 DBAPI 级别快速调用 fetchall()，但当 SQLAlchemy 的 CursorResult 要求执行 fetchall() 时出现缓慢，可能表示数据类型的处理速度较慢，例如 unicode 转换等：

# the DBAPI cursor is fast...
2    0.020    0.040    0.020    0.040 {method 'fetchall' of 'sqlite3.Cursor' objects}
...
# but SQLAlchemy's result proxy is slow, this is type-level processing
2    0.100    0.200    0.100    0.200 lib/sqlalchemy/engine/result.py:778(fetchall)

在某些情况下，后端可能正在进行不需要的类型级处理。更具体地说，看到类型 API 内的调用很慢更好，下面是我们使用这样一个类型时的情况：

from sqlalchemy import TypeDecorator
import time
class Foo(TypeDecorator):
    impl = String
    def process_result_value(self, value, thing):
        # intentionally add slowness for illustration purposes
        time.sleep(0.001)
        return value

这个有意慢操作的分析结果可以看起来像这样：

200    0.001    0.000    0.237    0.001 lib/sqlalchemy/sql/type_api.py:911(process)
200    0.001    0.000    0.236    0.001 test.py:28(process_result_value)
200    0.235    0.001    0.235    0.001 {time.sleep}

也就是说，我们在 type_api 系统内看到了很多昂贵的调用，而实际耗时的事情是 time.sleep() 调用。

确保检查 Dialect documentation 以了解此级别已知的性能调整建议，特别是对于像 Oracle 这样的数据库。可能有关于确保数值精度或字符串处理的系统可能并不在所有情况下都需要。

还可能存在更低级别的点导致行获取性能下降；例如，如果时间主要花在像 socket.receive() 这样的调用上，这可能表明除了网络连接本身外，其他所有东西都很快，而且花费了太多时间在网络上传输数据。

结果获取缓慢 - ORM

要检测 ORM 获取行的速度慢（这是性能关注的最常见领域），像 populate_state() 和 _instance() 这样的调用将说明单个 ORM 对象的加载情况：

# the ORM calls _instance for each ORM-loaded row it sees, and
# populate_state for each ORM-loaded row that results in the population
# of an object's attributes
220/20    0.001    0.000    0.010    0.000 lib/sqlalchemy/orm/loading.py:327(_instance)
220/20    0.000    0.000    0.009    0.000 lib/sqlalchemy/orm/loading.py:284(populate_state)

ORM 将行转换为 ORM 映射对象的速度慢是由于此操作的复杂性与 cPython 的开销相结合造成的。缓解这种情况的常见策略包括：

获取单个列而不是完整的实体，即：

select(User.id, User.name)

而不是：

select(User)

使用 Bundle 对象组织基于列的结果：

u_b = Bundle("user", User.id, User.name)
a_b = Bundle("address", Address.id, Address.email)
for user, address in session.execute(select(u_b, a_b).join(User.addresses)):
    ...

使用结果缓存 - 有关此的详细示例，请参见 Dogpile Caching。
考虑使用像 PyPy 这样的更快的解释器。

一次性分析的输出可能有点令人生畏，但经过一些练习后，它们会变得非常容易阅读。

另请参阅

性能 - 一套具有捆绑分析功能的性能演示。

查询分析

有时，仅仅记录 SQL（通过 Python 的 logging 模块启用或通过 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]

如果在操作之后记录了 myapp.somemessage，则知道完成 SQL 部分花费了 334ms。

记录 SQL 还会说明是否发出了数十个/数百个查询，这些查询可以更好地组织为更少的查询。在使用 SQLAlchemy ORM 时，“急加载”功能提供了部分（contains_eager()）或完全（joinedload()、subqueryload()）自动化此活动，但在没有 ORM 的“急加载”时，通常意味着使用连接以便在一个结果集中加载多个表的结果，而不是随着深度的增加而增加查询次数（即 r + r*r2 + r*r2*r3 …）

为了更长期地分析查询，或者实现应用程序端的“慢查询”监视器，可以使用事件拦截游标执行，使用以下类似的方法：

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):
    conn.info.setdefault("query_start_time", []).append(time.time())
    logger.debug("Start Query: %s", statement)
@event.listens_for(Engine, "after_cursor_execute")
def after_cursor_execute(conn, cursor, statement, parameters, context, executemany):
    total = time.time() - conn.info["query_start_time"].pop(-1)
    logger.debug("Query Complete!")
    logger.debug("Total Time: %f", total)

以上，我们使用ConnectionEvents.before_cursor_execute()和ConnectionEvents.after_cursor_execute()事件在语句执行时建立拦截点。我们在连接上附加一个计时器，使用info字典；在这里我们使用堆栈，偶尔情况下游标执行事件可能是嵌套的。

代码性能分析

如果日志显示个别查询花费了太长时间，您需要详细了解在数据库内部处理查询、通过网络发送结果、由 DBAPI 处理以及最终由 SQLAlchemy 的结果集和/或 ORM 层接收的时间。每个阶段都可能存在自己的瓶颈，具体取决于特定情况。

为此，您需要使用Python 性能分析模块。以下是一个将性能分析嵌入到上下文管理器中的简单示例：

import cProfile
import io
import pstats
import contextlib
@contextlib.contextmanager
def profiled():
    pr = cProfile.Profile()
    pr.enable()
    yield
    pr.disable()
    s = io.StringIO()
    ps = pstats.Stats(pr, stream=s).sort_stats("cumulative")
    ps.print_stats()
    # uncomment this to see who's calling what
    # ps.print_callers()
    print(s.getvalue())

对代码段进行性能分析：

with profiled():
    session.scalars(select(FooClass).where(FooClass.somevalue == 8)).all()

性能分析的输出可以让我们了解时间消耗在哪里。性能分析的一部分输出如下所示：

13726 function calls (13042 primitive calls) in 0.014 seconds
Ordered by: cumulative time
ncalls  tottime  percall  cumtime  percall filename:lineno(function)
222/21    0.001    0.000    0.011    0.001 lib/sqlalchemy/orm/loading.py:26(instances)
220/20    0.002    0.000    0.010    0.001 lib/sqlalchemy/orm/loading.py:327(_instance)
220/20    0.000    0.000    0.010    0.000 lib/sqlalchemy/orm/loading.py:284(populate_state)
   20    0.000    0.000    0.010    0.000 lib/sqlalchemy/orm/strategies.py:987(load_collection_from_subq)
   20    0.000    0.000    0.009    0.000 lib/sqlalchemy/orm/strategies.py:935(get)
    1    0.000    0.000    0.009    0.009 lib/sqlalchemy/orm/strategies.py:940(_load)
   21    0.000    0.000    0.008    0.000 lib/sqlalchemy/orm/strategies.py:942(<genexpr>)
    2    0.000    0.000    0.004    0.002 lib/sqlalchemy/orm/query.py:2400(__iter__)
    2    0.000    0.000    0.002    0.001 lib/sqlalchemy/orm/query.py:2414(_execute_and_instances)
    2    0.000    0.000    0.002    0.001 lib/sqlalchemy/engine/base.py:659(execute)
    2    0.000    0.000    0.002    0.001 lib/sqlalchemy/sql/elements.py:321(_execute_on_connection)
    2    0.000    0.000    0.002    0.001 lib/sqlalchemy/engine/base.py:788(_execute_clauseelement)
...

以上，我们可以看到instances() SQLAlchemy 函数被调用了 222 次（递归调用，从外部调用了 21 次），所有调用总共花了 0.011 秒。

执行速度慢

这些调用的具体细节可以告诉我们时间都花在哪里。例如，如果您看到在cursor.execute()内花费了时间，例如针对 DBAPI：

2    0.102    0.102    0.204    0.102 {method 'execute' of 'sqlite3.Cursor' objects}

这将表明数据库花费了很长时间才开始返回结果，这意味着您的查询应该被优化，可以通过添加索引或重组查询和/或底层架构来完成此任务。对查询计划的分析是有必要的，可以使用像 EXPLAIN、SHOW PLAN 等数据库后端提供的系统。

结果获取速度慢 - 核心

另一方面，如果你看到与获取行有关的成千上万次调用，或者对fetchall()的非常长时间的调用，这可能意味着你的查询返回的行数超出了预期，或者获取行本身的速度很慢。ORM 本身通常使用fetchall()来获取行（如果使用了Query.yield_per()选项，则使用fetchmany()）。

非常慢的fetchall()调用会被 DBAPI 级别上指示出异乎寻常的大量行：

2    0.300    0.600    0.300    0.600 {method 'fetchall' of 'sqlite3.Cursor' objects}

如果行数意外地很大，即使最终结果似乎没有很多行，也可能是笛卡尔积的结果 - 当多组行组合在一起而没有适当地连接表时。如果在复杂查询中使用了错误的Column对象，拉入意外的 FROM 子句，很容易在 SQLAlchemy Core 或 ORM 查询中产生这种行为。

另一方面，在 DBAPI 级别快速调用fetchall()，但当要求 SQLAlchemy 的CursorResult执行fetchall()时变慢，可能表明在处理数据类型（如 unicode 转换等）时存在缓慢：

# the DBAPI cursor is fast...
2    0.020    0.040    0.020    0.040 {method 'fetchall' of 'sqlite3.Cursor' objects}
...
# but SQLAlchemy's result proxy is slow, this is type-level processing
2    0.100    0.200    0.100    0.200 lib/sqlalchemy/engine/result.py:778(fetchall)

在某些情况下，后端可能正在进行不必要的类型级处理。更具体地说，看到类型 API 中的调用很慢更好，下面是当我们使用这样的类型时的情况：

from sqlalchemy import TypeDecorator
import time
class Foo(TypeDecorator):
    impl = String
    def process_result_value(self, value, thing):
        # intentionally add slowness for illustration purposes
        time.sleep(0.001)
        return value

这个故意缓慢操作的分析输出看起来像这样：

200    0.001    0.000    0.237    0.001 lib/sqlalchemy/sql/type_api.py:911(process)
200    0.001    0.000    0.236    0.001 test.py:28(process_result_value)
200    0.235    0.001    0.235    0.001 {time.sleep}

也就是说，我们在type_api系统中看到许多昂贵的调用，而实际耗时的是time.sleep()调用。

确保查看 Dialect 文档以获取关于已知性能调优建议的说明，特别是对于像 Oracle 这样的数据库。可能存在确保数字精度或字符串处理的系统，在某些情况下可能不需要。

还可能存在更多低级别的点导致行提取性能下降；例如，如果花费的时间似乎集中在像socket.receive()这样的调用上，那可能表明除了实际的网络连接外，一切都很快，而花费太多时间在数据在网络上传输上。

结果提取缓慢 - ORM

要检测 ORM 提取行的缓慢（这是性能关注的最常见领域），像populate_state()和_instance()这样的调用将说明单个 ORM 对象的填充：

# the ORM calls _instance for each ORM-loaded row it sees, and
# populate_state for each ORM-loaded row that results in the population
# of an object's attributes
220/20    0.001    0.000    0.010    0.000 lib/sqlalchemy/orm/loading.py:327(_instance)
220/20    0.000    0.000    0.009    0.000 lib/sqlalchemy/orm/loading.py:284(populate_state)

ORM 在将行转换为 ORM 映射对象时的缓慢是这个操作的复杂性与 cPython 的开销相结合的产物。减轻这种情况的常见策略包括：

获取单个列而不是完整实体，也就是：

select(User.id, User.name)

而不是：

select(User)

使用Bundle对象来组织基于列的结果：

u_b = Bundle("user", User.id, User.name)
a_b = Bundle("address", Address.id, Address.email)
for user, address in session.execute(select(u_b, a_b).join(User.addresses)):
    ...

使用结果缓存 - 参见 Dogpile Caching 以获取关于此的深入示例。
考虑使用像 PyPy 这样的更快解释器。

分析的输出可能有点令人生畏，但经过一些练习后，它们非常容易阅读。

另请参阅

性能 - 一套具有捆绑分析功能的性能演示。

我正在使用 ORM 插入 40 万行，速度真的很慢！

ORM 插入的性质已经改变，因为大多数包含的驱动程序在 SQLAlchemy 2.0 中都使用了带有 insertmanyvalues 支持的 RETURNING。详情请参见优化的 ORM 批量插入现在已经为除 MySQL 外的所有后端实现部分。

总的来说，除了 MySQL 外，SQLAlchemy 内置的驱动程序现在应该提供非常快速的 ORM 批量插入性能。

第三方驱动程序也可以通过一些小的代码更改选择使用新的批量基础设施，假设它们的后端支持必要的语法。SQLAlchemy 开发人员鼓励第三方方言的用户发布与这些驱动程序相关的问题，以便他们可以联系 SQLAlchemy 开发人员寻求帮助。

SqlAlchemy 2.0 中文文档（五十四）（4）https://developer.aliyun.com/article/1563182

SqlAlchemy 2.0 中文文档（五十四）（3）

如何对由 SQLAlchemy 驱动的应用进行性能分析？

查询分析

代码分析

执行速度慢

结果获取缓慢 - Core

结果获取缓慢 - ORM

查询分析

代码性能分析

执行速度慢

结果获取速度慢 - 核心

结果提取缓慢 - ORM

我正在使用 ORM 插入 40 万行，速度真的很慢！

热门文章

最新文章

相关电子书

热门

活动广场

任务中心

开发者评测

高校计划

乘风者计划

训练营

阿里云MVP

话题

直播

下载

镜像站

技术资料

插件

SqlAlchemy 2.0 中文文档（五十四）（3）

如何对由 SQLAlchemy 驱动的应用进行性能分析？

查询分析

代码分析

执行速度慢

结果获取缓慢 - Core

结果获取缓慢 - ORM

查询分析

代码性能分析

执行速度慢

结果获取速度慢 - 核心

结果提取缓慢 - ORM

我正在使用 ORM 插入 40 万行，速度真的很慢！

热门文章

最新文章

相关电子书