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

Шаг первый - включите логирование 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.

  См.также

  compilerext_caching - указания по применению атрибута 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, функция «eager loading» предоставляется для частичной (contains_eager()) или полной (joinedload(), subqueryload()) автоматизации этой деятельности, но без ORM «eager loading» обычно означает использование объединений, чтобы результаты из нескольких таблиц могли быть загружены в один набор результатов вместо умножения количества запросов по мере добавления глубины (т.е. 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.query(FooClass).filter(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, но затем медлительность, когда SQLAlchemy CursorResult просят сделать 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. Общие стратегии для снижения этой проблемы включают:

• получать отдельные столбцы вместо полных сущностей, то есть:

  session.query(User.id, User.name)

  вместо:

  session.query(User)

• Используйте объекты Bundle для организации результатов на основе столбцов:

  u_b = Bundle('user', User.id, User.name)
  a_b = Bundle('address', Address.id, Address.email)
  
  for user, address in session.query(u_b, a_b).join(User.addresses):
      # ...

• Используйте кэширование результатов - подробный пример этого см. в Кэширование Dogpile.

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

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