Производительность¶

Шаг первый - включите протоколирование SQL и проверьте, работает ли кэширование¶

Здесь мы хотим использовать технику, описанную в engine logging, и ищем операторы с индикатором [no key] или даже [dialect does not support caching]. Индикаторы, которые мы увидим для SQL-операторов, успешно участвующих в системе кэширования, будут указывать на [generated in Xs] при первом вызове операторов и затем [cached since Xs ago] для подавляющего большинства последующих операторов. Если [no key] преобладает, в частности, для операторов SELECT, или если кэширование полностью отключено из-за [dialect does not support caching], то это может быть причиной значительного снижения производительности.

Шаг второй - определить, какие конструкции препятствуют включению кэширования¶

Если утверждения не кэшируются, то в журнале приложения (только для SQLAlchemy 1.4.28 и выше) должны появляться ранние предупреждения, указывающие на диалекты, объекты TypeEngine и конструкции SQL, которые не участвуют в кэшировании.

Для определяемых пользователем типов данных, например, расширяющих TypeDecorator и UserDefinedType, предупреждения будут выглядеть следующим образом:

sqlalchemy.ext.SAWarning: MyType will not produce a cache key because the
``cache_ok`` attribute is not set to True. This can have significant
performance implications including some performance degradations in
comparison to prior SQLAlchemy versions. Set this attribute to True if this
type object's state is safe to use in a cache key, or False to disable this
warning.

Для пользовательских и сторонних SQL-элементов, например, построенных с использованием приемов, описанных в Пользовательские SQL-конструкции и расширение компиляции, эти предупреждения будут выглядеть следующим образом:

sqlalchemy.exc.SAWarning: Class MyClass will not make use of SQL
compilation caching as it does not set the 'inherit_cache' attribute to
``True``. This can have significant performance implications including some
performance degradations in comparison to prior SQLAlchemy versions. Set
this attribute to True if this object can make use of the cache key
generated by the superclass. Alternatively, this attribute may be set to
False which will disable this warning.

Для пользовательских и сторонних диалектов, использующих иерархию классов Dialect, предупреждения будут выглядеть следующим образом:

sqlalchemy.exc.SAWarning: Dialect database:driver will not make use of SQL
compilation caching as it does not set the 'supports_statement_cache'
attribute to ``True``. This can have significant performance implications
including some performance degradations in comparison to prior SQLAlchemy
versions. Dialect maintainers should seek to set this attribute to True
after appropriate development and testing for SQLAlchemy 1.4 caching
support. Alternatively, this attribute may be set to False which will
disable this warning.

Шаг третий - включение кэширования для заданных объектов и/или поиск альтернативных вариантов¶

Меры по устранению недостатка кэширования включают:

• Пересмотрите и установите значение ExternalType.cache_ok в значение True для всех пользовательских типов, которые расширяются от TypeDecorator, UserDefinedType, а также их подклассов, таких как PickleType. Устанавливайте это значение только в том случае, если пользовательский тип не включает никаких дополнительных атрибутов состояния, которые влияют на то, как он отображает SQL:

  class MyCustomType(TypeDecorator):
      cache_ok = True
      impl = String

  Если используемые типы взяты из сторонней библиотеки, проконсультируйтесь с ее сопровождающими, чтобы можно было скорректировать и выпустить ее.

  См.также

  ExternalType.cache_ok - справочная информация о требованиях к включению кэширования для пользовательских типов данных.

• Убедитесь, что для диалектов сторонних разработчиков установлено значение Dialect.supports_statement_cache на True. Это означает, что сопровождающие стороннего диалекта убедились в том, что их диалект работает с SQLAlchemy 1.4 или выше, и что их диалект не включает никаких особенностей компиляции, которые могут помешать кэшированию. Поскольку существуют некоторые общие шаблоны компиляции, которые действительно могут мешать кэшированию, важно, чтобы сопровождающие диалектов тщательно проверяли и тестировали это, корректируя все унаследованные шаблоны, которые не будут работать с кэшированием.

  См.также

  Кэширование для диалектов сторонних производителей - справочная информация и примеры участия сторонних диалектов в кэшировании SQL-операторов.

• Пользовательские классы SQL, включающие все конструкции DQL/DML, которые можно создать с помощью Пользовательские SQL-конструкции и расширение компиляции, а также специальные подклассы объектов типа Column или Table. Атрибут HasCacheKey.inherit_cache может быть установлен в значение True для тривиальных подклассов, которые не содержат никакой специфической для подкласса информации о состоянии, влияющей на компиляцию SQL.

  См.также

  Включение поддержки кэширования для пользовательских конструкций - рекомендации по применению атрибута HasCacheKey.inherit_cache.

Профилирование запросов¶

Иногда простое протоколирование 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 также покажет, не выполняются ли десятки/сотни запросов, которые можно было бы организовать в гораздо меньшем количестве. При использовании 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 и т.д., предоставляемые бэкендом базы данных.

Медленное получение результатов - ядро¶

Если же вы видите много тысяч вызовов, связанных с получением строк, или очень длинные вызовы fetchall(), это может означать, что ваш запрос возвращает больше строк, чем ожидалось, или что само получение строк происходит медленно. Сам ORM обычно использует fetchall() для получения строк (или fetchmany(), если используется опция Query.yield_per()).

О неумеренно большом количестве строк будет свидетельствовать очень медленный вызов fetchall() на уровне DBAPI:

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

Неожиданно большое количество строк, даже если конечный результат не кажется большим, может быть следствием картезианского произведения - когда несколько наборов строк объединяются вместе без соответствующего объединения таблиц. Часто такое поведение легко получить с помощью SQLAlchemy Core или ORM-запросов, если в сложном запросе используются неправильные объекты Column, втягивающие дополнительные предложения FROM, которые оказываются неожиданными.

С другой стороны, быстрый вызов fetchall() на уровне DBAPI, а затем медлительность при запросе CursorResult в SQLAlchemy на выполнение fetchall(), может указывать на медлительность при обработке типов данных, например, при преобразовании юникода и т.п:

# 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-mapped является результатом сложности этой операции в сочетании с накладными расходами 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.

• Рассмотрим более быстрый интерпретатор, например, PyPy.

Вывод профиля может показаться несколько пугающим, но после некоторой практики его легко читать.